A Stroke Of Luck
April 9th, 2010One of my customers reported a really subtle bug having to do with a keyboard shortcut for a command. I’m going to change some facts to protect the innocent, but imagine I got a report:
“Every time I press cmd-N to create a new document and start typing, instead of accepting the text, it just beeps at me.”
This seems impossible to me. Creating a new document and typing into it is fundamental to my product. Surely if it was broken I would know from my own daily testing of the application. I try diligently to reproduce it, but of course, I can’t. Create a new document. Start typing. Everything works, everybody’s happy. Except the person who reported the bug.
At some point in my tinkering I stumble upon the bug. Beep. I can’t type. There it is! What a drag. This application sucks!
Now that I’ve seen and heard the bug with my own eyes, I’m more committed than ever to fixing it. But how on earth did I do it? I try several more times and am unable to reproduce the problem.
I have only spotted the issue once in my dozens of trials, yet the customer claims it affects him every single time. What explains this? Maybe it simply doesn’t happen as often on my Mac as it does on his. My thoughts turn to the brute force of AppleScript. If this happens only once in a blue moon on my Mac, surely I can reproduce it by running a script that iterates the test conditions hundreds or thousands of times. I open AppleScript Editor and enter the following:
tell application "System Events" repeat 100 times keystroke "n" using command down keystroke "Testing typing" end repeat end tell
Nothing! Even after running it 1000 times, nothing. How can this be? How could something so common for the customer, something that I saw myself once, be so difficult to reproduce on my Mac?
After playing around a bit more, I started to reproduce it more readily. What was happening? I couldn’t figure it out, but something “felt” a little different when I reproduced it. I thought carefully about the parameters of the bug, as exemplified (I thought) by my script:
- The command key is pressed.
- The N key is pressed.
- The N key is released.
- The command key is released.
- Typing into the new document is attempted.
I looked again at the script. Perhaps this “keystroke” command is not literal enough. For all I know it’s circumventing the normal key events that get generated when you type on the keyboard. On a lark, I modified the script to be more explicit:
tell application "System Events"
repeat 100 times
key down {command}
key down "n"
key up "n"
key up {command}
key down "x"
key up "x"
end repeat
end tell
Here we have a more literal match with my analysis of what happens. Hold down the command key, press the N key, release, then type something. In this case I just type an x character because I figure any typing is enough to trigger the bug.
I ran this 100 times as well and no luck. The bug is simply not reproducible through scripting. I guess I’ll have to figure out what conditions are making it more likely for the customer to run into the bug. Maybe he has some 3rd party software that is interfering. Or … wait a minute.
tell application "System Events"
repeat 100 times
key down {command}
key down "n"
key up {command}
key up "n"
key down "x"
key up "x"
end repeat
end tell
I ran the modified script and the bug immediately exhibited itself. So what changed? Look carefully and you’ll see that my previous script assumed that when a keyboard shortcut is pressed, there is a sort of nested symmetry to the order of pressing and releasing the keys. When I press keyboard shortcuts, I hold the modifier keys down throughout the stroke, and release only after the letter key has been released. But this customer has muscle memory that inclines him to instead release the keys in the order they were pressed. When he releases the N key, the command key has “long” since been released.
This subtle difference turns out to trigger a bug in my event monitoring code that, to make a long story short, robs first responder status from the default view in the document. So when he creates a new document, there is no first responder, and his typing just causes a bunch of beeps. When I create a new document, there’s always a first responder, so I don’t see the bug.
As difficult as this bug was to track down, it would have been near impossible without the theory testing, disproving, and ultimately proving tool of using AppleScript and System Events to zero on in the behavior. Sometimes when the steps a customer provides to reproduce a bug seem exactly the same as what you’re doing, you’re just not trying hard enough to find the difference.
April 9th, 2010 at 3:30 pm
The miserable pain of not knowing where to begin solving something is only matched by the utterly god-like feeling of figuring it all out. The moment where the magic Tetris piece slides into place in your mind, suddenly clearing out the huge mess that sat before it. You pay a steep price for that kind of high but it’s a one-of-a-kind sense of professional gratification.
More profitable than getting high through other means, too.
April 9th, 2010 at 3:46 pm
This reminds me of Shipley’s debugging post from a while back. What a great article! Thanks Daniel.
April 9th, 2010 at 4:52 pm
I’ve been publishing a “Learn to Speak AppleScript” series on my site lately — and Part 2 deals specifically with how literal you need to be sometimes when communicating with AppleScript.
Reading this, however, makes me realize that I should have really drawn a bigger line under that point as it regards **sequencing** your commands… and I am going to link to your story to illustrate this.
Thanks for sharing, Daniel!
April 9th, 2010 at 6:19 pm
Kick ASS.
You’re a better man than I. I would have cheated and just forced first responder (the beep gives it away that the app was the responder than handled the event) and *maybe* I would have woken up a year later (I’m like that) and decided I was lame and then not had the discipline and debugging skills you possess to track down exactly what was going on.
April 9th, 2010 at 7:43 pm
When typing Command-W, I always release the command key first, because it’s what feels natural (try doing both ways as fast as you can). With Command-N I do the opposite because I hold Command with the left thumb, hit N with my right first finger and then release Command. But if I type Command-N with my right hand and the right-side Command key, then Command is released first like for Command-W. So maybe it was just a matter of which hand each of you uses.
April 9th, 2010 at 9:08 pm
So how does one turn these types of applescript sequences into regression tests before releases? Most unit tests are quite different (I’m not a GUI programmer) as they interrogate functionality and ensure behavior before and after refactoring.
April 10th, 2010 at 12:05 am
Wow. That much thought into tracking an isolated report. Now this is professionalism!
April 10th, 2010 at 1:07 am
Excellent story from the debugging trenches.
You might want to correct “4. The command key is pressed.” I think it should say “released”?
April 10th, 2010 at 5:22 am
The Talmud says “There is no pleasure like the resolution of a doubt.”
Are you talking about Marsedit?
I tried to reproduce the bug (don’t know whether your latest build has corrected it) and I found that if I press Cmd +N and try to lift my finger from the Cmd key while holding the N, meanwhile I had [without wishing to] ‘opened’ thirteen new documents.
I had never before used keystrokes to open new docs in Marsedit, so I don’t know whether this multiple document opening is a ‘feature/bug’ that has always been there. Has it?
I wondered whether there was a limit to the number of new documents I could open this way – just by holding down on Cmd + N.
I stopped at 51, fearing that I might have to close each individually. However, on quitting Marsedit, they all closed without a whimper.
April 10th, 2010 at 1:30 pm
David – the article is slightly fictionalized because I don’t want to share specifics that might give away details of a product I’m working on.
That said, the “rapid fire new windows” behavior you observed is standard behavior for any app that creates new documents. Try it in Safari, for example. It’s a behavior of the system to auto-repeat a keystroke if you hold down the key for a certain duration.
When I describe in the post the command key being lifted after the letter key, I’m still talking about a process that takes a fraction of a second, so it’s still short enough that you don’t get the key repeat.
April 10th, 2010 at 6:04 pm
It seems to me that this would have been easier to track down if there was an input event logging facility built into your app. Then you could have asked the user to enable this logging facility, reproduce the bug, then email you the log.
Maybe it’s worth it to implement such a facility for all future apps?
April 10th, 2010 at 6:09 pm
Cameron – the problem is I don’t know how I would have guessed to consider the events themselves, until after I had already solved the problem. It’s one of those things where, sure in retrospecting knowing the order and types of events the user was sending would lead to the solution, but I was convinced it was some other reason he was seeing the bug and I wasn’t.
April 10th, 2010 at 8:21 pm
Try debugging an AppleScript app with AppleScript like that! Arrgghh! Loved the story though–been there.
April 10th, 2010 at 8:23 pm
BooneJS – about the unit testing question, I’m not really an expert but generally speaking I would say that the particulars of the keyboard events and the scripting that led me to track down this bug are too large of scope to be permanently committed as unit tests. They are the particular details that led to an underlying bug in my application’s code. SO the underlying bug is what, philosophically, should have unit test alterations made to.
April 11th, 2010 at 9:36 am
Good story and nice write-up. Do you think you ever would have thought to try the asymmetric key releasing if not for staring at the AppleScript code?
April 11th, 2010 at 10:54 am
Robby – I don’t know. It’s hard to speculate what lucky break you will get and where it will lead the mind. I definitely think the tool of AppleScript for automating and formalizing what I was testing helped me to think about the program more narrowly.
April 11th, 2010 at 2:05 pm
Daniel – Thank you for the reply, and yes, I see that it happens with Safari. I should have tried that first.
So how long is ‘just long enough’ to open one new document but not more?
Are these published figures?
Is there a lab with engineers measuring how long the slowest person in a sample takes before they lift their finger from the ‘n’ key?
April 11th, 2010 at 11:34 pm
David,
The delay is customizable. The Keyboard pane in System Preferences will allow you to control how the duration of the pause before it starts repeating, and then how quickly it repeats.
April 12th, 2010 at 5:17 pm
“So how long is “˜just long enough”™ to open one new document but not more?”
You can change this setting in Keyboard system preferences.
About the default value, I don’t know how Apple determined it though.