Beefy Boxes and Bandwidth Generously Provided by pair Networks
Perl: the Markov chain saw

The 10 stages of Bug hunting and the sweet smell of success

by tachyon (Chancellor)
on Sep 18, 2003 at 13:42 UTC ( #292385=perlmeditation: print w/replies, xml ) Need Help??

So we have this rather large application. mod_perl, squid, Apache, MySQL and some Perl and C glue. So I am looking at the database and go "I don't like the look of that..." and so it begins - the hunt for the bug.....

Stage 1 - Begin Self Delusion (aka How Hard Can it Be?)

On the surface it seems like it will be pretty simple. A script which accesses the DB is iterating through a list. When it presents an item from the list it updates its status from 0 ie to be done, to 1 as in in progress. When it finishes if updates the flag to 2 ie done. Simple enough. Only problem is that there are a hell of a lot more 1s in there than there should be. For some reason the task is being commenced but not completed. A quick test show that for every task completed we have effectively 3 iterations through the DB list leaving one 2 and two 1 flags. Should be simple I think ;-) Someone has just called the get widget more than once. Well actually no.....they have not.....

Stage 2 - End Self Delusion (aka This might take a while)

OK so there are no obvious errors. It ain't gonna be that easy. So we start to strip things away. Now I was accessing the widget through the proxy. And it was working before I was doing this. That MUST be the problem. Strip off the proxy.....and.....problem remains.....


OK I think. It was running fine under vanilla cgi and it is now not. Copy to vanilla CGI and all is well....and so I get the first sniff of the problem.....

Stage 3 - Back to Basics (aka Warn is your friend)

Time to pepper the code with warn "blah" and see what is going on. Lets have a look at the error log now. Ah interesting, we are getting a double POST to the script (the first debug warn was warn "Entered script $$\n") followed by others:

Entered script 7064 POST End of script Entered script 7064 POST End of script

So now we can see the problem happening but why.....

Stage 4 - I think I am getting close (aka You wish)

Ah the almighty power of self delusion. So it now looks like it is a mod perl related double POST issue. But how is it related exactly? We are using a highly cut down version of CGI::Simple with just the basic header, param, query string and cookie methods. Why? Well it is twice as fast as, 10% the size, has methods that Apache::Registry doesn't and is damn near as fast as A::R without cookies and faster if you are using cookies. Doesn't care if it is running under mod_perl or vanilla. Big deal if it is broken! Perhaps that is the problem? Surely it must be.....

Stage 5 - Assumptions Assumptions (aka Begin Fruitless Search)

So let's convert to and see if the problem goes away I think. OK so the interface is the same, so it should not be hard. Oops 500 internal - forgot I added that $q->cookie()->bake method. Oops another 500 - $q->no_cache. OK so we have it running. And the problem seems fixed.....

Stage 6 - More Self Delusion

So it LOOKS like changing to has fixed it, must be a bug in my measly 300 lines of code. So off we go. Looking this way and looking that. When it was still broken using almost identical code to (mod perl associated) I begin to wonder.....I was sure fixed it....Double check. Oh, it actually didn't.....

Stage 6 - s/Fruitless Search|More Self Delusion/Denial/

Surely I didn't really just waste all that time? Must be a browser/mod_perl/somebody_elses_problem BUG. Sheesh it even happens with Google for 'double POST bug mod_perl'....waste more time.....what about 'IE browser bug'....Hang on why don't I just try Netscape and Firebird (after all I am only using IE because that is what the end users will be using)....Damn, can't blame Bill.....Double check just to be sure ;-).....

Stage 7 - KISS (aka Strip it down to the bare minimum test case)

OK so lets prepare a really simple test case. Useful to post to Perlmonks in desparation if it gets really desperate. Yup there we go < 15 lines that reproduces the problem. Hang on.....

Stage 8 - The light bulb goes on

So I now have a trivial case that reproduces the problem, but that's the problem, it is so trivial it is almost self evident that there is no problem with that code....

Stage 9 - You always find your keys (and the bug) in the last place you look

So what else was there? Only httpd.conf left really. Berate self, how could I have neglected that. Anyway here is the snippet from httpd.conf:
PerlModule Apache::Filter PerlModule Apache::Dynagzip <Location /modperl/> SetHandler perl-script PerlHandler Apache::Registry Apache::RegistryFilter Apache::Dyna +gzip # PerlSetVar Filter On PerlSetVar UseCGIHeadersFromScript Off PerlSendHeader Off PerlSetupEnv On AllowOverride None Options ExecCGI Order allow,deny Allow from all </Location>

Yes we are using Apache::Dynagzip - great module BTW. Check the online docs (not carefully enough) Yup all looks OK. So comment out bits, restart Apache, test, problem refuses to go away although some amusing things happen. The most interesting occurred when I commented out the bit shown (killing the gzip stream...sort of):

Back to Test ScriptAAG@%#(*&GDG&$%#!@SES@%$$%TGSKUJYHT* ^%@%#$DFGF(*(%$FSDGF^@%$$DGDF*%%#Q#$DSG(*&^$WDS

So what was that? Well that is the output of Apache::Registry (the legible bit of the test case) and an undecoded gzip stream. Why two? Wasn't two the problem. Could my presumption about Apache::Dynagzip (i.e., it just could not be the problem because it is on the output stream) be WRONG? Reread the docs, carefully this time. Oops, you don't use Apache::Registry with Apache::RegistryFilter and Apache::Dynagzip. If I had read the docs more carefully in the first place I would have noted that. So the problem was that we had two different Apache modules essentially splitting one request into two.....amazing it has not caused more problems really!

Stage 10 - The sweet taste of success


Nothing like ending a session on a satisfactory note. Being Australian there is only one way to celebrate. Did I say smell? I meant taste. If you ever get to OZ try a VB. It's a beer. Bottoms up, and happy hunting.


Fix one problem create another. The config directives shown above using Apache::RegistryFilter and Apache::Dynagzip (but removing Apache::Registry from the chain) fix the double POST....BUT...stop cookies from working properly. This config apparently gives you mod_perl, cookies and on the fly gzip compression. Here's hoping! Some small test cases look promising.

PerlModule Apache::Registry PerlModule Apache::Filter PerlModule Apache::Dynagzip <Location /modperl/> SetHandler perl-script PerlHandler Apache::Registry Apache::Dynagzip PerlSetVar Filter On PerlSetVar UseCGIHeadersFromScript On PerlSendHeader On PerlSetupEnv On AllowOverride None Options +ExecCGI Order allow,deny Allow from all </Location>




Replies are listed 'Best First'.
Re: The 10 stages of Bug hunting and the sweet smell of success
by bunnyman (Hermit) on Sep 18, 2003 at 16:57 UTC
Re: The 10 stages of Bug hunting and the sweet smell of success
by Anonymous Monk on Sep 19, 2003 at 03:52 UTC
    aka Strip it down to the bare minimum test case

    Isn't this step 1 everytime you find an inconsistency?

      In a perfect world, possibly. I doubt seriously that everyone is disciplined enough to do that though.. I agree totally with the 'well I just changed that bit, I think, and it worked before then... ' approach.


Re: The 10 stages of Bug hunting and the sweet smell of success
by Ryszard (Priest) on Sep 19, 2003 at 08:27 UTC
    If you ever get to OZ try a VB. It's a beer. Bottoms up, and happy hunting.
    Or even better a, cascade or hahn prem...

Log In?

What's my password?
Create A New User
Node Status?
node history
Node Type: perlmeditation [id://292385]
Approved by Corion
Front-paged by gmax
[choroba]: that's from the last year, right?
[choroba]: Pretty similar to his talk at YAPC::EU 2016

How do I use this? | Other CB clients
Other Users?
Others imbibing at the Monastery: (6)
As of 2017-09-19 18:04 GMT
Find Nodes?
    Voting Booth?
    During the recent solar eclipse, I:

    Results (226 votes). Check out past polls.