Click/Load Broken #4

pvolk · 2013-07-12T00:03:34Z

So I was able to confirm this bug by downgrading from 0.5.448 (the one with the bug) to 0.5.441 (no bug) on the firefox versions page.

To reproduce:

Go to www.hotwire.com
Click the "Cars" tab at the top
Type in some search criteria (anything will work) and click search.
HERE'S THE BUG
Wait for the set of results to load up fully. In the .441 version you'll see two load events (this is correct). If you run steps 1-3 in .448 you will see one load, followed by one click event (the click event is really a load event -- I've confirmed through some discover reports).

Can you help fix please! Donation incoming by the way... this is the best Omniture debugger and the only one kept up to date.

simpsora · 2013-07-17T03:04:24Z

Hi pvolk,

Thanks for the bug! I'll have a look. At the moment, I'm just seeing a single Omniture request on that page (to om.hotwire.com; verified on the Net tab). Any other steps I need to take to get the two events to fire?

simpsora · 2013-07-17T14:25:54Z

Hi again,

So far I'm unable to duplicate the issue exactly.

.441:

s8351126405376, key=3b3310ff9588cf73ace86eb3d6a3671b
00:06:01.162:  decodeUrl: processing key=3b3310ff9588cf73ace86eb3d6a3671b (doneLoading=true)
00:06:01.164:  report: found Omniture 'pe' parameter; resetting eventType (was=click; now=click)
Click event (previous page) | Omniture | Thu Jul 18 2013 00:06:01 GMT+1000 (EST) | 3b3310ff9588cf73ace86eb3d6a3671b

1994564917, key=89478a27ae3d2b5ea9362d3ea212ad16
00:06:04.287:  decodeUrl: processing key=89478a27ae3d2b5ea9362d3ea212ad16 (doneLoading=false)
Load event | Urchin | Thu Jul 18 2013 00:06:04 GMT+1000 (EST) | 89478a27ae3d2b5ea9362d3ea212ad16 | 200 OK

1865964543, key=84422309e410ec966be9167658860701
00:06:08.773:  decodeUrl: processing key=84422309e410ec966be9167658860701 (doneLoading=false)
Load event | Urchin | Thu Jul 18 2013 00:06:08 GMT+1000 (EST) | 84422309e410ec966be9167658860701 | 200 OK

One Omniture click event (from the previous page), two GA load events

.451:

s83246884664281, key=c2765a00fcab171813c2ef53130f5a50
00:12:56.084:  decodeUrl: processing key=c2765a00fcab171813c2ef53130f5a50 (doneLoading=true)
[Omniture event not shown in Omnibug panel (expired)]

44182241, key=19262c8df0a547ec1cda5baa7513f744
00:13:00.861:  decodeUrl: processing key=19262c8df0a547ec1cda5baa7513f744 (doneLoading=false)
Load event | Google Analytics | Thu Jul 18 2013 00:13:00 GMT+1000 (EST) | 19262c8df0a547ec1cda5baa7513f744 | 200 OK

178770639, key=3d4e2e58650da29686acac79a532e415
00:13:02.938:  decodeUrl: processing key=3d4e2e58650da29686acac79a532e415 (doneLoading=false)
Load event | Google Analytics | Thu Jul 18 2013 00:13:02 GMT+1000 (EST) | 3d4e2e58650da29686acac79a532e415 | 200 OK

One Omniture click event (from the previous page) (not shown), two GA load events

The only difference between the two is in the later version, the Omniture click event from the previous page (most likely fired on form submit) is not shown, because it has expired.

Telling load and click events apart is a bit tricky, because there's nothing generic in the URLs that differentiate them. Omnibug knows when the top-level page starts loading and when it finishes, and any analytics requests that come in during that time are considered load events. Any events occurring after top-level page load is complete are considered click events. This can lead to events being mistakenly marked as the wrong type in some circumstances.

I will keep investigating, but if you could please repeat your test in .448 a few times I would appreciate it. Ideally you could repeat it a couple of times on different computers -- I'm curious to know if it occurs reliably, or if it is related to timing.

pvolk · 2013-07-17T17:07:54Z

Hey Ross.

Thanks for looking into this! I put together this PDF with some pictures
and more details to hopefully clarify my reproduction steps from the
ticket. Thanks for the clarification on how you determine load/click events
(I was about to ask that question anyways but I figured it had to be hacked
together). I was also able to reproduce this using the methods in the PDF
file on 3 different machines using the same Firefox version. There is also
some click/load wonkiness in the chrome alpha/beta/whatever but i just
dismissed that as alpha/beta/whatever issues :)

Anyways, let me know if I can help more with this.

EDIT: Looks like github doesn't like email attachments. Here's a link to the PDF in google drive.
https://docs.google.com/file/d/0B0cgwMsvcYAdZmh5UW43ZkwzUVU/edit?usp=sharing

On Wed, Jul 17, 2013 at 7:25 AM, Ross Simpson notifications@github.comwrote:

Hi again,

So far I'm unable to duplicate the issue exactly.
.441:

s8351126405376, key=3b3310ff9588cf73ace86eb3d6a3671b
00:06:01.162: decodeUrl: processing key=3b3310ff9588cf73ace86eb3d6a3671b (doneLoading=true)
00:06:01.164: report: found Omniture 'pe' parameter; resetting eventType (was=click; now=click)
Click event (previous page) | Omniture | Thu Jul 18 2013 00:06:01 GMT+1000 (EST) | 3b3310ff9588cf73ace86eb3d6a3671b

1994564917, key=89478a27ae3d2b5ea9362d3ea212ad16
00:06:04.287: decodeUrl: processing key=89478a27ae3d2b5ea9362d3ea212ad16 (doneLoading=false)
Load event | Urchin | Thu Jul 18 2013 00:06:04 GMT+1000 (EST) | 89478a27ae3d2b5ea9362d3ea212ad16 | 200 OK

1865964543, key=84422309e410ec966be9167658860701
00:06:08.773: decodeUrl: processing key=84422309e410ec966be9167658860701 (doneLoading=false)
Load event | Urchin | Thu Jul 18 2013 00:06:08 GMT+1000 (EST) | 84422309e410ec966be9167658860701 | 200 OK

One Omniture click event (from the previous page), two GA load events
.451:

s83246884664281, key=c2765a00fcab171813c2ef53130f5a50
00:12:56.084: decodeUrl: processing key=c2765a00fcab171813c2ef53130f5a50 (doneLoading=true)
[Omniture event not shown in Omnibug panel (expired)]

44182241, key=19262c8df0a547ec1cda5baa7513f744
00:13:00.861: decodeUrl: processing key=19262c8df0a547ec1cda5baa7513f744 (doneLoading=false)
Load event | Google Analytics | Thu Jul 18 2013 00:13:00 GMT+1000 (EST) | 19262c8df0a547ec1cda5baa7513f744 | 200 OK

178770639, key=3d4e2e58650da29686acac79a532e415
00:13:02.938: decodeUrl: processing key=3d4e2e58650da29686acac79a532e415 (doneLoading=false)
Load event | Google Analytics | Thu Jul 18 2013 00:13:02 GMT+1000 (EST) | 3d4e2e58650da29686acac79a532e415 | 200 OK

One Omniture click event (from the previous page) (not shown), two GA load
events

The only difference between the two is in the later version, the Omniture
click event from the previous page (most likely fired on form submit) is
not shown, because it has expired.

Telling load and click events apart is a bit tricky, because there's
nothing generic in the URLs that differentiate them. Omnibug knows when the
top-level page starts loading and when it finishes, and any analytics
requests that come in during that time are considered load events. Any
events occurring after top-level page load is complete are considered
click events. This can lead to events being mistakenly marked as the
wrong type in some circumstances.

I will keep investigating, but if you could please repeat your test in
.448 a few times I would appreciate it. Ideally you could repeat it a
couple of times on different computers -- I'm curious to know if it occurs
reliably, or if it is related to timing.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/4#issuecomment-21116358
.

simpsora · 2013-07-19T15:01:05Z

Paul,

Thanks for the extra detail, that helps clarify the steps to reproduce. I'm sorry to say that I still can't reproduce it, though. I tried on Windows 7, OS X 10.7, and Linux (Debian), all with Firefox 22. I was able to get .441 to behave as detailed in your PDF, but no matter what I try I can't get the later version(s) of Omnibug to show the load event as a click event.

Just to show we're on the same page, here's what I'm seeing:

To take this further, please do the following:

Install the new version of Omnibug (0.5.456, http://www.rosssimpson.com/dev/omnibug-0.5.456.xpi)
Start Firefox from the command line and pass in the -console flag (firefox.exe -console)
Go into about:config in the browser
Set the following properties to a true boolean value:
extensions.logging.enabled
browser.dom.window.dump.enabled
Repeat the testing
Send me the output from the console window

The above settings will enable a console where Omnibug's low-level debugging info will be printed. If you could, please run a single test which exhibits the problem (open the browser, open Firebug, navigate to www.hotwire.com, perform a cars search) and send me the full output from the console. This should help me dig deeper into what's causing the mismatched event types. I'm guessing it's a timing issue, but hard to say for sure.

Cheers!

pvolk · 2013-07-22T17:02:31Z

You know, I think you are in a version test that doesn't have the issue.

Can you follow the same steps doing an Airfare search (there are no tests
that would effect reproducing this bug? Any search will work. On the
results page you will see the load event followed by a click event (even
though the click event is actually a load event).

If you still cannot reproduce using this method, I'll follow your
directions.

On Fri, Jul 19, 2013 at 8:01 AM, Ross Simpson notifications@github.comwrote:

Paul,

Thanks for the extra detail, that helps clarify the steps to reproduce.
I'm sorry to say that I still can't reproduce it, though. I tried on
Windows 7, OS X 10.7, and Linux (Debian), all with Firefox 22. I was able
to get .441 to behave as detailed in your PDF, but no matter what I try I
can't get the later version(s) of Omnibug to show the load event as a click
event.

Just to show we're on the same page, here's what I'm seeing:
[image: omnibug_working_455]https://f.cloud.github.com/assets/735585/826327/cdb5dda6-f082-11e2-80d4-6e99dcfa7d99.png

To take this further, please do the following:

Install the new version of Omnibug (0.5.456,
http://www.rosssimpson.com/dev/omnibug-0.5.456.xpi)

Start Firefox from the command line and pass in the -console flag (firefox.exe
-console)

Go into about:config in the browser

Set the following properties to a true boolean value:
extensions.logging.enabled
browser.dom.window.dump.enabled

Repeat the testing

Send me the output from the console window

The above settings will enable a console where Omnibug's low-level
debugging info will be printed. If you could, please run a single test
which exhibits the problem (open the browser, open Firebug, navigate to
www.hotwire.com, perform a cars search) and send me the full output from
the console. This should help me dig deeper into what's causing the
mismatched event types. I'm guessing it's a timing issue, but hard to say
for sure.

Cheers!

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/4#issuecomment-21254801
.

Paul Volk

Mobile: +1-408-905-8489
more about.me http://goo.gl/a2FPN

simpsora · 2013-08-11T13:18:28Z

Hi Paul,

(Sorry for the delay -- was out of the country for a little while)

I've just tried again with Airfare searches, and unfortunately still am not able to reproduce the click events. For the airfare search, I see two load events in Omnibug (pageNames air.searching and air.results), and two corresponding Omniture calls in the net tab.

I am determined to fix this issue, but am a bit stumped at the moment. If you could follow those steps in my previous message, that will give me some idea of what's going on.

Thanks!

Matthew-Peters-au · 2013-08-12T04:48:38Z

Hello Gents,
I have experienced the same issue, is there any way I can help contribute to help isolating the issue?

Cheers
Matthew

simpsora · 2013-08-12T04:57:17Z

Hi Matthew,

Yes please! If you could write up a detailed set of steps to reproduce, I would very much appreciate it. Starting URL, steps, OS/browser type & versions, Omnibug versions (which do or do not exhibit the problem), etc. It's quite a frustrating bug, and it would be very helpful to have a test case that's reproducible in one of my environments.

Thanks!

Matthew-Peters-au · 2013-08-13T03:24:59Z

Hello,
I'll try and see if I can replicate the issue in my production/live website.
I'm using a number of platforms and browsers, but today for example I'm using:
OS: Windows 7 x64 bit
Browser: Mozilla Firefox 21.0
Firebug: 1.11.4
Omnibug: 0.5.456

Essentially, the page load event which is usually labelled in Omnibug as a blue [LOAD] event is coming up in Omnibug as a green [CLICK] event.

From what I can see, the usual LOAD label appears when the omniture/sitecatalyst/adobe analytics image beacon is appears between DOMContentLoaded and Load. (using the NET panel in firebug)
However, quite often my page load event is appearing in the timeline just after the red line (or Load) which is why I believe Omnibug is colouring it green.

In fact the issue is intermittent, and largely dependant on when the the image beacon appears on the time line.

Matthew-Peters-au · 2013-08-13T03:55:31Z

What if we looked at the value of the 'pe' query string parameter on the image beacon?

If pe is:
null: Colour Blue: [Page Load Event]
lnk_o: Colour Green: [Custom Click Event]
lnk_e: Colour Red: [Exit Link Event]
lnk_d Colour Gold [Download Event]

pvolk · 2013-08-13T23:03:06Z

Hey Ross,

I finally did the console dump and have a screenshot to go with it. If you follow my original steps while searching for a flight, you'll be able to reproduce this. Screenshot attached.

Here is the console dump following those steps with a flight search:

3:55:27 PM.177: destroyContext: context[25851]

3:55:27 PM.200: initContext: context[34165]; browser[22138]
3:55:27 PM.205: expireRequests: processing 0 requests; context[34165]
3:55:27 PM.216: expireRequests: done (0 remaining)
ALX_NS_PH.CBA: yes
3:55:27 PM.640: loadedContext: context[34165]; browser[22138]
3:55:27 PM.643: processRequests: processing 0 requests; context[34165]; browser
[22138]
3:55:27 PM.650: processRequests: done (0 remaining)
3:55:27 PM.717: OmnibugSidePanel: inited
3:55:28 PM.091: onStateChange (context[34165]; browser[22138]):
name=http://om.hotwire.com/b/ss/hotwirecom/1/H.23.2/s71771649544887?AQB=
1&ndh=1&t=13%2F7%2F2013%2015%3A55...
flags=STATE_START, STATE_IS_REQUEST, STATE_IS_BROKEN, STATE_SECURE_MED
key=de737955cd30f71313b06b7c8f1d76ca
parentUrl=http://www.hotwire.com/

3:55:28 PM.119: decodeUrl: processing key=de737955cd30f71313b06b7c8f1d76ca (don
eLoading=false)
3:55:28 PM.143: report: wrote entry for de737955cd30f71313b06b7c8f1d76ca (event
Type=load)
3:55:28 PM.156: onStateChange: adding request (key=de737955cd30f71313b06b7c8f1d
76ca) to module
3:55:28 PM.262: responseObserver: key=de737955cd30f71313b06b7c8f1d76ca; sc=200;
st=OK
3:55:28 PM.267: responseObserver: updating request in list for key=de737955cd30
f71313b06b7c8f1d76ca
ALX_NS_PH.CBA: yes
3:55:50 PM.096: destroyContext: context[34165]

3:55:50 PM.122: initContext: context[130]; browser[22138]
3:55:50 PM.129: expireRequests: processing 1 requests; context[130]
3:55:50 PM.138: expireRequests: processing de737955cd30f71313b06b7c8f1d76ca (br
owser[22138]; age=22.048): 3:55:50 PM.145: expired; removing entry
3:55:50 PM.146: expireRequests: done (0 remaining)
ALX_NS_PH.CBA: yes
3:55:50 PM.584: loadedContext: context[130]; browser[22138]
3:55:50 PM.586: processRequests: processing 0 requests; context[130]; browser[2
2138]
3:55:50 PM.591: processRequests: done (0 remaining)
3:55:50 PM.669: OmnibugSidePanel: inited
3:55:50 PM.986: onStateChange (context[130]; browser[22138]):
name=http://om.hotwire.com/b/ss/hotwirecom/1/H.23.2/s73087483616165?AQB=
1&ndh=1&t=13%2F7%2F2013%2015%3A55...
flags=STATE_START, STATE_IS_REQUEST, STATE_IS_BROKEN, STATE_SECURE_MED
key=a558a6048a0563ea5eae5e01f0566298
parentUrl=http://www.hotwire.com/air/results.jsp?searchTokenId=1&backBut
tonInputId=index

3:55:51 PM.035: decodeUrl: processing key=a558a6048a0563ea5eae5e01f0566298 (don
eLoading=false)
3:55:51 PM.058: report: wrote entry for a558a6048a0563ea5eae5e01f0566298 (event
Type=load)
3:55:51 PM.068: onStateChange: adding request (key=a558a6048a0563ea5eae5e01f056
6298) to module
3:55:51 PM.122: onStateChange (context[130]; browser[22138]):
name=http://ad.doubleclick.net/adi/N4764.AdOps_BookingBuddy/B5764929;sz=
300x250;click=http://ads.expedia....
flags=STATE_START, STATE_IS_REQUEST, STATE_IS_DOCUMENT, STATE_IS_WINDOW,
STATE_IS_BROKEN, STATE_SECURE_MED, STATE_SECURE_LOW
key=2d34be12eb81c7a12ccf61716702bfa7
parentUrl=http://www.hotwire.com/air/results.jsp?searchTokenId=1&backBut
tonInputId=index

3:55:51 PM.159: decodeUrl: processing key=2d34be12eb81c7a12ccf61716702bfa7 (don
eLoading=false)
3:55:51 PM.174: report: wrote entry for 2d34be12eb81c7a12ccf61716702bfa7 (event
Type=load)
3:55:51 PM.179: onStateChange: adding request (key=2d34be12eb81c7a12ccf61716702
bfa7) to module
ALX_NS_PH.CBA: yes
ALX_NS_PH.CBA: yes
3:55:51 PM.284: responseObserver: key=a558a6048a0563ea5eae5e01f0566298; sc=200;
st=OK
3:55:51 PM.290: responseObserver: updating request in list for key=a558a6048a05
63ea5eae5e01f0566298
3:55:51 PM.353: responseObserver: key=2d34be12eb81c7a12ccf61716702bfa7; sc=200;
st=OK
3:55:51 PM.360: responseObserver: updating request in list for key=2d34be12eb81
c7a12ccf61716702bfa7
ALX_NS_PH.CBA: yes
3:55:54 PM.344: onStateChange (context[130]; browser[22138]):
name=http://om.hotwire.com/b/ss/hotwirecom/1/H.23.2/s78923502011865?AQB=
1&ndh=1&t=13%2F7%2F2013%2015%3A55...
flags=STATE_START, STATE_IS_REQUEST, STATE_IS_BROKEN, STATE_SECURE_MED
key=67495fcb63322361190af2975dd52bf6
parentUrl=http://www.hotwire.com/air/results.jsp?searchTokenId=1&backBut
tonInputId=index

3:55:54 PM.373: decodeUrl: processing key=67495fcb63322361190af2975dd52bf6 (don
eLoading=true)
3:55:54 PM.396: report: wrote entry for 67495fcb63322361190af2975dd52bf6 (event
Type=click)
3:55:54 PM.406: onStateChange: adding request (key=67495fcb63322361190af2975dd5
2bf6) to module
3:55:54 PM.583: responseObserver: key=67495fcb63322361190af2975dd52bf6; sc=200;
st=OK
3:55:54 PM.589: responseObserver: updating request in list for key=67495fcb6332
2361190af2975dd52bf6

Matthew-Peters-au · 2013-08-14T03:27:45Z

Hi Pvolk,
I can see what you mean:

I think the reason is because the first call on your SERP Container (Search Engine Results Page) will be identified as a page [LOAD] (blue) and the second call when the results are populated into the DIV's within the commonResultsPage div's will be treated as a [CLICK] (green).

So a fix could be to get omni bug to look at the value of the 'pe' parameter within the Omniture image beacon so that:

If the value of the query string parameter 'pe' is:

null then Colour Blue: [Page Load Event]
lnk_o then Colour Green: [Custom Click Event]
lnk_e then Colour Red: [Exit Link Event]
lnk_d then Colour Gold [Download Event]

simpsora · 2013-08-15T22:07:32Z

Sorry for the delay responding -- I have some time set aside this weekend to tackle this problem.

Paul, thanks for the details, they will be quite helpful.
Matthew, thanks also for your input.

As I mentioned above, differentiating click and load events is a bit tricky to do in a generic fashion. In Omniture it's a little easier, because of the pe parameter. Omnibug already does check pe, and overrides the event type to 'click' when pe is present. The fact that this used to work fine (in .441 and before) makes me think that my refactoring has changed this behavior, albeit in a non-obvious way.

I will spend time this weekend trying to knock this one out for good. More info to follow.

Code in common.js will at some point be pulled back into top-level common/ dir. Fixed issue #4 relating to load events getting marked as click events (was due primarily to typo in check for Omniture `pe' param check).

simpsora · 2013-08-23T14:09:17Z

Hi guys,

I'm sure I already posted this last week, but it appears not. I think I've fixed this issue. It does seem to have been an issue with the code that handles the `pe' parameter. I have refactored that code a bit, both to fix the issue, and to make it testable (there are now several unit tests around this particular issue).

I prepared a pre-release build which contains the fix for just this issue. If you would, please download and install the following build:

http://www.rosssimpson.com/dev/tmp/omnibug-0.5.499.xpi

That should fix the click/load issue, finally. Please give that version a try and let me know how it goes!

Matthew-Peters-au · 2013-08-26T04:43:24Z

Hello Ross,
I've given it a go and its looking good 👍
Will let you know if any problems arise.

pvolk · 2013-08-26T17:18:39Z

Hey Ross,

This looks good to me. Thanks for the work getting this fixed!

Out of curiosity, what did the fix end up being?

simpsora · 2013-09-15T05:40:10Z

Thanks for your help, guys. The problem, embarrassingly, was using an incorrect variable for the `pe' check (some variable names changed during a recent refactor, and I ended up checking the name of the provider, rather than the code). It looked correct, just wasn't.

I've publicly released version 0.5.500, which contains this fix.

Cheers!

ghost assigned simpsora Jul 17, 2013

simpsora added a commit that referenced this issue Jul 19, 2013

Logging cleanup; extra logging detail (for #4)

f8f7f9f

simpsora closed this as completed Sep 15, 2013

simpsora mentioned this issue Sep 15, 2013

Omniture click events logged as load events #6

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Click/Load Broken #4

Click/Load Broken #4

pvolk commented Jul 12, 2013

simpsora commented Jul 17, 2013

simpsora commented Jul 17, 2013

pvolk commented Jul 17, 2013

simpsora commented Jul 19, 2013

pvolk commented Jul 22, 2013

simpsora commented Aug 11, 2013

Matthew-Peters-au commented Aug 12, 2013

simpsora commented Aug 12, 2013

Matthew-Peters-au commented Aug 13, 2013

Matthew-Peters-au commented Aug 13, 2013

pvolk commented Aug 13, 2013

Matthew-Peters-au commented Aug 14, 2013

simpsora commented Aug 15, 2013

simpsora commented Aug 23, 2013

Matthew-Peters-au commented Aug 26, 2013

pvolk commented Aug 26, 2013

simpsora commented Sep 15, 2013

Click/Load Broken #4

Click/Load Broken #4

Comments

pvolk commented Jul 12, 2013

simpsora commented Jul 17, 2013

simpsora commented Jul 17, 2013

.441:

.451:

pvolk commented Jul 17, 2013

simpsora commented Jul 19, 2013

pvolk commented Jul 22, 2013

simpsora commented Aug 11, 2013

Matthew-Peters-au commented Aug 12, 2013

simpsora commented Aug 12, 2013

Matthew-Peters-au commented Aug 13, 2013

Matthew-Peters-au commented Aug 13, 2013

pvolk commented Aug 13, 2013

Matthew-Peters-au commented Aug 14, 2013

simpsora commented Aug 15, 2013

simpsora commented Aug 23, 2013

Matthew-Peters-au commented Aug 26, 2013

pvolk commented Aug 26, 2013

simpsora commented Sep 15, 2013