CGI Debugging: always the last place you look.

[swngnmonk]

While this is aimed at those monks writing CGI applications, this should be familiar to anyone suffering through the search for an obscure bug. As a preface - this isn't really a perl issue, as much as it is just one more story about the hell that is debugging.

We're in the final stages of testing a commerce application written w/ mod_perl, primarily based on CGI::Application. It's pretty straightforward stuff - user decides they want to buy something, they select the desired Credit Card to purchase with, they confirm or cancel the purchase, they get a thankyou page and an email if they confirm, cancel page otherwise.

Development has been somwhat scattershot lately - the project got pushed back in the schedule, we worked on other things, the final bits were added in a somewhat haphazard fashion. One of the last major bits of code that was added recently was responsible for those confirmation emails. Everything seemed fine.

In the earlier stages, our QA group was testing functionality, and was only using IE. In the last week, they started serious browser-testing, and that's when the strangest bug came in:

"When using Safari on the Mac, I click 'confirm purchase', and I get two confirmation emails. This works fine on the PC using IE."

WTF?

So I test it on my own machine (Linux/Firefox). Sure enough, two emails!

I spend a *long* time looking at the code. No loops, no recursion, nothing that even remotely suggests things being called twice. I litter the appropriate runmode with plenty of debugging statements. Sure enough, it really is being called twice!

During all this time, the biggest mystery is this: only this runmode is affected. Every other runmode works perfectly. There has to be something wrong with this runmode!

Time to bring in the coworkers. Plenty of suggestions. What about the AccessHandler that you wrote? Nope. Is it really making two calls? Sure enough, dumping $$ into the error log shows two different Apache procs handling the request. "It's gotta be a redirect." Nope, not that either.

Finally, a break. "Try it in Lynx." Start the purchase process, get to the confirmation page. Wait... It's javascript.. Can't submit in Lynx.. What does the source show?? BINGO.

<tr><td>
  <a href="?rm=purchase">
  <input type="button" class="button" 
   value="&gt; CONFIRM ORDER"
  onclick="document.location='?rm=purchase'">
  </a><br><br>
  <a href="?rm=cancel_purchase">
  <input type="button" class="button" value="&gt; 
   CANCEL ORDER"
onclick="document.location='?rm=cancel_purchase'">
</a>
</td></tr>

See it?

The javascript was put in place so that the user's decision to purchase or cancel did not need to be determined by the runmode - the user would go right to the appropriate runmode. Unfortunately, the AHREF tag around it, under some browsers, causes the form to be submitted twice. *That* was the problem.

The HTML had been written by a contractor ages ago. They had taken the bare-bones no-javascript template I had written (with working forms), and made it pretty. QA checked it under IE (where the form was submitted only once), it still worked. And sat there, lurking for months, until we finally did browser testing and it came up. Yowza.

There's really not much of a moral to the story. Can't really blame anyone for it (yes, it was an HTML problem, but things *did* work on some levels). Can definitely slap my forehead as to how long it took to figure it out. Learned another debugging trick or two, which is always good.

I guess all I can say is question everything - up until I saw that javascript, it never occurred to me that some browsers could be sending two identical requests. And thank god for Lynx, which is always handy for bringing things into focus.

[Vautrin]

I learned a long time ago that the key to debugging applications -- esp. CGI applications -- is to log information about the state of the program to a file. Using an in house logger with the ability to change verbosity (preferably from the program, i.e. so you can have somebody e-mail you the logs if there are problems) allows looking at a script and seeing exactly what is going on. It can be a pain setting it up, but there is nothing sweeter then saying "there's been 2 emails, and we see from the log that function send_email was called twice"

[geohar]

Surely the browsers which call the code twice are actually more correct. They execute the javascript and the hyperlink, which seems to be what the html above mandates (not sure what the standard says, but I'd be suprised if they said only one should get executed). Also, kudos for testing Safari on the mac. Lots of people leave non M$ browser testing out, or figure mozilla covers the 'rest'.

[diotalevi]

Are you sure about that? Once you've instructed the browser to navigate elsewhere it shouldn't still attempt to retrieve some other web page. That should be a trip into onunload and then to the new page with no excursion for the other page which would have been loaded otherwise.

I'd consider the browser that requested the page twice to be incorrect and curse it a bit. I'd still fix the page so it worked correctly regardless but be sure to harbor some ill will to the poorly performing browser.

[Anonymous Monk]

Actually, I wouldn't fault the browser. The html is invalid and the behaviour is undefined.

[EvdB]

I would say that you were lucky if the effect of a double submission was only a double email - are you sure that you are not doing anything else twice as well?

Although the browser is misbehaving you should take double submissions into account and code to protect against them. After all if the page is taking a long time to load the user may hit it again. In my app I have something like this:

# in cgi: (have loaded the correct order into $order)
$order->submit;

# in order module.
sub submit {
    my $self = shift;
    return 1 if $self->submitted;
    ...
}

This means that it is not possible to submit the order twice. Also all post submit actions are dealt with in the module, such as sending email confirmations.

[bageler]

usually when you want to handle an onclick it either
1) will not navigate someone to a link, or
2) returns false so the href will not be followed

[swngnmonk]

So a follow-up as to how things were resolved.

Thankfully, the structure of the underlying billing objects was such that the CC was only ever going to be billed once. Additional checking in the run-mode was added to check for a double-submit, but it may not have caught this error (because two requests were coming in simultaneously, the DB might not have been updated in time). That said, a second user click is now addressed properly in the CGI, not just in the underlying API.

Additionally, the form submit was changed from a GET method to a POST method. While it won't explicitely protect against the user double-click, it will throw up the "Are you sure you want to re-submit?" message in most modern browsers. At least it will make the user think twice about their actions.

Thinking about things further, it can be viewed as a cautionary tale for developers who have other people handle the HTML in their templates. The original templates I developed contained template logic & minimal HTML only. When I handed them off, I had tested the app fully, it worked as expected. But I made the mistake of not carefully testing it when I got the templates back (only cursory checks). One of the reasons this took so long to debug was that it never occured to me that the fancy HTML added later could be the culprit. From now on, I'll be vetting every template that someone else touches.