Double execution, my bad

Yesterday was a bug fighting day for me. I might add, twas a frustrating one at that. Here's the scenario:

We have a simple subscribe box allowing users to receive email updates for certain categories if a new job appears in that category. If there is a new user, it should prompt them for their user info. If it is an existing user, it should prompt them for their pin. The problem that I was seeing is that a new user was being prompted for a pin, indicating that this was not a new user at all. The odd part was that it worked in my dev environment but not in our beta or prod environments, same exact code.

So... digging in, I set several cfdumps throughout the application followed by a cfabort.
(Side note: for a cool way to view a stack trace from several levels deep, see Ben Nadel).
I didn't really see anything from that info. All it told me is somehow the record for the user was being created before the code I was observing. That was a head scratcher because I was at the beginning of the code execution. I looked all over the relevant pages for a cflocation or a window.location thinking that somehow it was being recursive. Nothing. I looked at the fusebox parsed file and there was nothing in there that told me it was circling back. Now what? Since this was in beta and we didn't want to turn RDS on, I couldn't do the step through. That wouldn't have helped me anyway knowing now what the issue was. I did turn on debugging and that didn't give me much. I decided to set up a sql trace and found that there was indeed a double execution going on but it simply wasn't showing in my browser.

After lunch I came back and searched on coldfusion and some play on the words "double exexution" and found a blogging from the cf4 days about how some code was causing double execution on an image tag that had a non cfoutputted variable as the src. The explanation came back that the browsesr was seeing the # and going back to the page again for the image causing it to run twice. That got me to thinking. Maybe I should be looking in the iis logs. Sure enough, there it was:

2008-08-26 19:41:27 ******** GET ****** 80 - 69.41.14.80 libcurl-agent/1.0 200 0 0
2008-08-26 19:41:31 ******** GET ****** 80 - ***.***.***.*** Mozilla/5.0+(Windows;+U;+Windows+NT+5.1;+en-US;+rv:1.9.0.1)+Gecko/2008070208+Firefox/3.0.1 200 0 0

One was my browser... but before that was a libcurl-agent. What was that? I was thinking it was some of our data gathering visit trackers but I came up empty googling libcurl in combo with their names. Finally I researched the ip. Using arin.net, I found that this "bot" belonged to

Michigan Online Group MOG-69-41-0-0 (NET-69-41-0-0-1)
69.41.0.0 - 69.41.15.255
Covenant Eyes, Inc. MOG-69-41-14-0 (NET-69-41-14-0-1)
69.41.14.0 - 69.41.14.255

Oh man... Covenant Eyes. That is my integrity software that I am running locally. The filter service gets wind of the site that I want to visit, rushes out and see's it before I do in order to check its content, then flags my system to say that its ok to visit. That was essentially creating the user before my browser could get to it. By the time I got there, it was percieved as a return visit. Man... I just wasted 7 hrs looking into it (I'm obsessive I know). I'm all in favor of running integrity software because we're only as strong as our weakest moments. I still like what Covenant Eyes does, but if you forget about how it works it can cause a few headaches and wasted hours. The fix to this is to set the site url to permanent allow under the Filter History and Settings area. That will stop the filter from "pre-visiting" the sites that you are trying to debug.