dialog 'POST /wsapi/interaction_data' gets response 'HTTP/1.1 413 Request Entity Too Large'

[jrgm]

I was working with @jbonacci and @skinny using FF15 against dev.myfavoritebeer.org. While it worked for me ok, I noticed in network traces that I was getting a 413 response on /wsapi/interaction_data. The POST was trying to send >40KB of data (and we cap at 10K of course). I don't know how I got in this state though. I'll note that FF15/osx is my main browser and this process has been up since midnight Sunday. The local_timestamp's in the json data are for event streams on Monday and Tuesday (sorry, I've been focussed on stage obviously this week and only rarely looked at dev). I can give you the POST data to ponder over.

Marking 5-star for the train after train-2012-04-27.

--- request ---
(Request-Line)     POST /wsapi/interaction_data HTTP/1.1
Host               dev.diresworb.org
User-Agent         Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:15.0) Gecko/15.0 Firefox/15.0a1
Accept             application/json;text/plain
Accept-Language    en-us,hu;q=0.9,fi;q=0.8,zh-cn;q=0.7,el;q=0.6,zh-tw;q=0.4,zh;q=0.3,de;q=0.2,en;q=0.1
Accept-Encoding    gzip, deflate
DNT                1
Connection         keep-alive
X-Requested-With   XMLHttpRequest
Content-Type       application/json; charset=UTF-8
Referer            https://dev.diresworb.org/sign_in
Content-Length     41349
Cookie             browserid_state_634063=bDA2BGPDihHCkgIQPMOQwpfDjMO3w6o.RjzDqsK9w5PChsKYwoTDnMOjGCrDojsDM8O2woXDkW4FHUA5wqvDjMOEw5N0w60fZnNNwrwdwpbCpwbCmMKwwoLDhAIGGAEsAMOAW8OAw71SA8KUGV1VWsO4esK9WsOBw5TCkDTDsnHCllFvAMKHe14owoV9.1336599578593.3600000.GMKHwrRgF3fDrAJjI8OBw75tbcKnc2ZZwrlXIcKfwo9nw5tNwrDCl3rCsBEw
Pragma             no-cache
Cache-Control      no-cache

--- response ---
(Status-Line)      HTTP/1.1 413 Request Entity Too Large
Server             nginx/1.0.14
Date               Wed, 09 May 2012 22:18:15 GMT
Transfer-Encoding  chunked
Connection         keep-alive
X-Powered-By       Express

[jrgm]

So, one way to reproduce this (but the event_streams don't look similar to what I had for my initial report) is this:

1. set firefox to File->Work Offline
2. open, try to use the dialog, close the dialog (or just open/close many times).

The event streams accumulate. Take firefox back into online mode and open the dialog again. If you accumulated enough data you will get the 413 for more than 10K data in the POST.

[jrgm]

Oh, heh. Here's how you really reproduce this:

1. enter an email address that will cause email to be sent out and dialog to enter the 3 second polling loop on e.g., /wsapi/user_creation_status
2. let the dialog sit there for 10 or 12 minutes (the phone rang, email is delayed, someone at the door...)
3. You'll now have >10K of data to send the next time dialog is launched (and it never gets reset).

[lloyd]

with respect to this bug, there are at least three things going on:

1. we're collecting a ton of data during polling that is not valuable. perhaps we should not be doing this. this would suggest surpressing xhr events (only capture xhr errors)
2. interaction blobs accumulate when you're offline. Maybe we should have a max backlog? we need some way to deal with this
3. the client should delete blobs when it encounters a 413 error. Idea being this is low value data, and we should be mucking things up for it.
4. if the above explorations do not solve the problem, then we need to consider upping the 10k limit

Our goal here should be 99.9% of interaction blobs captured...

[lloyd]

The above commit fixes #3 mentioned above. But this issue needs to stay open. remaining action items:

1. Client should remember what ids you use #1, IP should check for primary support upon email addition #2, Create browserid.org site content #4 from above
2. perhaps we should introduce a client side upper bound as well, and if blobs are above that, don't even try to post?

[jrgm]

@lloyd also noted that this feature will not be enabled in prod (or in stage), so with the above PR, I'll change this to 4-star and we can address the remaining points for the next train.

[jrgm]

confirming again in dev the fix for #3 413 -> clear data from local storage, and also checked the /wsapi/session_context in stage train-2012.05.14 is returning '"data_sample_rate":0 so no interaction data is collected in stage.

[jrgm]

@jbonacci see #1567 (comment) above. The primary issue is fixed but the problem is not completely fixed. Looking back at what's left, I think I will split out the issues to separate issues, and then close this one and verify (actually have already verified against dev last weekend, but will re-check the actuall train branch).

[jrgm]

verified in dev (can't be verified in stage train-2012.05.14; the code is in that train, but the kpi feature is disabled there).
Closing and marking verified. Splitting out the other three points in #1567 (comment)

[jrgm]

Hmm, now this feels like I overkilled, but I filed GH-1619, GH-1620, GH-1621, GH-1622 as followups.

[lloyd]

overkill wfm.