Visit_id is not set at the beginning of some page visits.

[dreisman]

If a socket closes improperly, then calls to sock.send() will fail, and the error won't get caught. This will cause the TaskManager to die without failing gracefully (for instance, the TaskManager won't be able to save the browser profile).

An example of this in the wild. The first stack trace was caused by an error in the DataAggregator, and the second is the actual socket error. It is unknown if the two are related.

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/multiprocess/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/local/lib/python2.7/dist-packages/multiprocess/process.py", line 114, in run
    self._target(*self._args, **self._kwargs)
  File "/home/ubuntu/[REMOVED]/OpenWPM/automation/DataAggregator/DataAggregator.py", line 56, in DataAggregator
    process_query(query, curr, logger)
  File "/home/ubuntu/[REMOVED]/OpenWPM/automation/DataAggregator/DataAggregator.py", line 89, in process_query
    curr.execute(statement,args)
IntegrityError: NOT NULL constraint failed: http_requests.visit_id

Traceback (most recent call last):
  File "/home/ubuntu/[REMOVED]/census_crawl_id_detection.py", line 70, in <module>
    manager.execute_command_sequence(command_sequence)
  File "/home/ubuntu/[REMOVED]/OpenWPM/automation/TaskManager.py", line 528, in execute_command_sequence
    self._distribute_command(command_sequence, index)
  File "/home/ubuntu/[REMOVED]/OpenWPM/automation/TaskManager.py", line 367, in _distribute_command
    thread = self._start_thread(browser, command_sequence)
  File "/home/ubuntu/[REMOVED]/OpenWPM/automation/TaskManager.py", line 424, in _start_thread
    (self.next_visit_id, browser.crawl_id, command_sequence.url)))
  File "/home/ubuntu/[REMOVED]OpenWPM/automation/SocketInterface.py", line 133, in send
    sent = self.sock.send(msg[totalsent:])
socket.error: [Errno 32] Broken pipe

[englehardt]

This doesn't seem to be an issue with the socket (or the DataAggregator). The original error was IntegrityError: NOT NULL constraint failed: http_requests.visit_id which causes the DataAggregator to crash. Once that fails, any socket that tries to send information to the aggregator will throw a Broken pipe exception. Both of these are expected (and desired for critical errors like a null visit id).

So the question is, under what condition are we sending a null visit_id?

[englehardt]

Let's use the string "null" when the visit_id is null and see where in the new crawls it's set to null. I imagine this will largely be non-essential requests that we'd want to drop anyway (i.e. noise from the browser that we should disable). @dreisman, will you be able to commit this?

[englehardt]

This was implemented in 0ec97d1. Let's check the latest crawl data to see which urls have this issue.

[dreisman]

In converting the March 2017 25k id detection crawl, I found exactly one http_requests row that had visit_id set to -1. It was the first request of a page load (visit_id=6052, top_url='http://supersport.com'). We believe this is the result of a race condition in the extension, where the visit_id is not set before it starts getting the first page when the browser restarts.

We also are afraid that there may be a case where the visit_id is set to the an old visit id for a new site_visit, and we aren't catching that.

Attempt to measure:

From the 2017-03 id detection, it looks like there are about 200 sites out of the 25,000 for which this MAY have happened. These are 200 sites for which we do not see a row where top_url == url in http_requests.

Ideally we may want the browser to block until the extension confirms it got a new visit_id, before visiting the new page. See #135.

In the meantime, it be best to drop these rows if it's happening on a small enough scale. The problem seems to only affect the first page load request.

[englehardt]

Proposed fix is in #135.

[vringar]

While this error report is still valid and unfixed the fix for it is begin discussed in another issue so this one doesn't provide any additional value. Especially seeing how the observable behaviour is completely different by now.