Logo Questions Linux Laravel Mysql Ubuntu Git Menu
HTML CSS JAVASCRIPT SQL PYTHON PHP BOOTSTRAP JAVA JQUERY R React Kotlin
 

Excessive Latency on CORS AJAX Request to Local WSGI Server in Chrome

Tags:

python

javascript

jquery

http

wsgi

Setup

Two WSGI servers running locally on different ports. One server returns an html page containing javascript that does a cross-origin ajax request to the other WSGI server using jQuery.

origin_server.py Serves the html at http://localhost:9010.

#!/usr/bin/env python

from wsgiref.simple_server import make_server


def origin_html(environ, start_response):
    status = '200 OK'
    response_headers = [('Content-Type', 'text/html')]
    start_response(status, response_headers)    

    f = open('./index.html', 'rb')
    return [f.read()]

httpd = make_server('localhost', 9010, origin_html)
httpd.serve_forever()

cors_server.py Serves the cross-origin resource that the javascript will request.

#!/usr/bin/env python

from wsgiref.simple_server import make_server
import json


def cors_json(environ, start_response):
    status = '200 OK'
    response_headers = [
        ('Content-Type', 'application/json'),
        ('Access-Control-Allow-Origin', '*')
    ]
    start_response(status, response_headers)

    return [json.dumps({'foo': 'bar'})]

httpd = make_server('localhost', 9011, cors_json)
httpd.serve_forever()

index.html The page served by origin_sever.py.

<!DOCTYPE html>
<html>
    <head>
        <script
            type="text/javascript"
            src="https://code.jquery.com/jquery-2.1.3.min.js"
            >
        </script>

        <script type="text/javascript">
            $(document).ready(function () { 
                console.log('Doing the thing.');
                $.get('http://localhost:9011').done(function (data) {
                    console.log('Got the thing', data);
                });
            });
        </script>
    </head>
    <body>
        Beep boop.
    </body>
</html>

Code above on github here: https://github.com/thatjpk/local-wsgi-cors-ajax

Versions of stuff for reference:

  • Mid 2012 MacBook Pro, OS X 10.10
  • Python 2.7.6
  • wsgiref 0.1.2
  • Chrome 40.0.2214.93 (Extensions disabled and settings reset for testing.)
  • Firefox 35.0.1

Problem

Given the above I can open up two terminals, start origin_server.py in one, and cors_server.py in the other, then open a browser tab and point it to the origin server at http://localhost:9010/. This loads the page, and does the cross-origin request.

Ideally, the latencies should all be very low because it's all local. However, I'm consistently seeing latencies for the cross-origin request of well over ten seconds. What's bizzarre is I've only ever seen this in Chrome in a non-incognito window. Firefox, curl, httpie, and Chrome incognito tabs on the same machine all complete the cross-origin request in sub-10ms, while non-incognito Chrome tabs take three orders of magnitude longer.

If I cut CORS out of the equation, and just put http://localhost:9011 in the Chrome address bar, the json loads into view immediately. This apparently only happens when the request comes from javascript.

If try to make another request to cors_server.py while a request to it in Chrome is "pending", the second request will wait until the first one completes). This means the first request is somehow tying up the wsgi server for a long time before execution reaches the handler in cors_server.py.

There's definitely more going on when the request takes forever to complete. I collected the following using tcpdump -i lo0 dst port 9011 or src port 9011.

This is a request from httpie (http get localhost:9011) that completes quickly.

17:33:57.176028 IP localhost.64723 > localhost.9011: Flags [S], seq 2244357563, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910553864 ecr 0,sackOK,eol], length 0
17:33:57.176089 IP localhost.9011 > localhost.64723: Flags [S.], seq 1494086712, ack 2244357564, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910553864 ecr 910553864,sackOK,eol], length 0
17:33:57.176103 IP localhost.64723 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176113 IP localhost.9011 > localhost.64723: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176145 IP localhost.64723 > localhost.9011: Flags [P.], seq 1:136, ack 1, win 12759, options [nop,nop,TS val 910553864 ecr 910553864], length 135
17:33:57.176158 IP localhost.9011 > localhost.64723: Flags [.], ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176760 IP localhost.9011 > localhost.64723: Flags [P.], seq 1:18, ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 17
17:33:57.176781 IP localhost.64723 > localhost.9011: Flags [.], ack 18, win 12758, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176811 IP localhost.9011 > localhost.64723: Flags [P.], seq 18:55, ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 37
17:33:57.176823 IP localhost.64723 > localhost.9011: Flags [.], ack 55, win 12757, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176834 IP localhost.9011 > localhost.64723: Flags [P.], seq 55:92, ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 37
17:33:57.176844 IP localhost.64723 > localhost.9011: Flags [.], ack 92, win 12756, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176857 IP localhost.9011 > localhost.64723: Flags [P.], seq 92:178, ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 86
17:33:57.176866 IP localhost.64723 > localhost.9011: Flags [.], ack 178, win 12753, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176878 IP localhost.9011 > localhost.64723: Flags [P.], seq 178:192, ack 136, win 12755, options [nop,nop,TS val 910553864 ecr 910553864], length 14
17:33:57.176886 IP localhost.64723 > localhost.9011: Flags [.], ack 192, win 12753, options [nop,nop,TS val 910553864 ecr 910553864], length 0
17:33:57.176961 IP localhost.9011 > localhost.64723: Flags [F.], seq 192, ack 136, win 12755, options [nop,nop,TS val 910553865 ecr 910553864], length 0
17:33:57.176975 IP localhost.64723 > localhost.9011: Flags [.], ack 193, win 12753, options [nop,nop,TS val 910553865 ecr 910553865], length 0
17:33:57.176980 IP localhost.9011 > localhost.64723: Flags [.], ack 136, win 12755, options [nop,nop,TS val 910553865 ecr 910553865], length 0
17:33:57.182034 IP localhost.64723 > localhost.9011: Flags [F.], seq 136, ack 193, win 12753, options [nop,nop,TS val 910553870 ecr 910553865], length 0
17:33:57.182095 IP localhost.9011 > localhost.64723: Flags [.], ack 137, win 12755, options [nop,nop,TS val 910553870 ecr 910553870], length 0

This is a request from Firefox that completes quickly.

18:12:57.416741 IP localhost.65089 > localhost.9011: Flags [S], seq 2202457533, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 912890306 ecr 0,sackOK,eol], length 0
18:12:57.416794 IP localhost.9011 > localhost.65089: Flags [S.], seq 1807873905, ack 2202457534, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 912890306 ecr 912890306,sackOK,eol], length 0
18:12:57.416806 IP localhost.65089 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.416818 IP localhost.9011 > localhost.65089: Flags [.], ack 1, win 12759, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.416883 IP localhost.65089 > localhost.9011: Flags [P.], seq 1:346, ack 1, win 12759, options [nop,nop,TS val 912890306 ecr 912890306], length 345
18:12:57.416899 IP localhost.9011 > localhost.65089: Flags [.], ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417478 IP localhost.9011 > localhost.65089: Flags [P.], seq 1:18, ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 17
18:12:57.417492 IP localhost.65089 > localhost.9011: Flags [.], ack 18, win 12758, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417516 IP localhost.9011 > localhost.65089: Flags [P.], seq 18:55, ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 37
18:12:57.417538 IP localhost.65089 > localhost.9011: Flags [.], ack 55, win 12757, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417548 IP localhost.9011 > localhost.65089: Flags [P.], seq 55:92, ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 37
18:12:57.417555 IP localhost.65089 > localhost.9011: Flags [.], ack 92, win 12756, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417562 IP localhost.9011 > localhost.65089: Flags [P.], seq 92:192, ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 100
18:12:57.417569 IP localhost.65089 > localhost.9011: Flags [.], ack 192, win 12753, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417618 IP localhost.9011 > localhost.65089: Flags [F.], seq 192, ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417629 IP localhost.65089 > localhost.9011: Flags [.], ack 193, win 12753, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417634 IP localhost.9011 > localhost.65089: Flags [.], ack 346, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417638 IP localhost.65089 > localhost.9011: Flags [F.], seq 346, ack 193, win 12753, options [nop,nop,TS val 912890306 ecr 912890306], length 0
18:12:57.417647 IP localhost.9011 > localhost.65089: Flags [.], ack 347, win 12748, options [nop,nop,TS val 912890306 ecr 912890306], length 0

This is a request from a Chrome incognito tab that completes quickly.

17:28:10.096905 IP6 localhost.64691 > localhost.9011: Flags [S], seq 2861078667, win 65535, options [mss 16324,nop,wscale 5,nop,nop,TS val 910207638 ecr 0,sackOK,eol], length 0
17:28:10.096926 IP6 localhost.9011 > localhost.64691: Flags [R.], seq 0, ack 2861078668, win 0, length 0
17:28:10.097010 IP localhost.64692 > localhost.9011: Flags [S], seq 3615577823, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910207638 ecr 0,sackOK,eol], length 0
17:28:10.097056 IP localhost.9011 > localhost.64692: Flags [S.], seq 3533709271, ack 3615577824, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910207638 ecr 910207638,sackOK,eol], length 0
17:28:10.097066 IP localhost.64692 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910207638 ecr 910207638], length 0
17:28:10.097075 IP localhost.9011 > localhost.64692: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910207638 ecr 910207638], length 0
17:28:10.097274 IP localhost.64692 > localhost.9011: Flags [P.], seq 1:373, ack 1, win 12759, options [nop,nop,TS val 910207638 ecr 910207638], length 372
17:28:10.097293 IP localhost.9011 > localhost.64692: Flags [.], ack 373, win 12747, options [nop,nop,TS val 910207638 ecr 910207638], length 0
17:28:10.098108 IP localhost.9011 > localhost.64692: Flags [P.], seq 1:18, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207638], length 17
17:28:10.098131 IP localhost.64692 > localhost.9011: Flags [.], ack 18, win 12758, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098166 IP localhost.9011 > localhost.64692: Flags [P.], seq 18:55, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 37
17:28:10.098184 IP localhost.64692 > localhost.9011: Flags [.], ack 55, win 12757, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098212 IP localhost.9011 > localhost.64692: Flags [P.], seq 55:92, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 37
17:28:10.098232 IP localhost.64692 > localhost.9011: Flags [.], ack 92, win 12756, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098246 IP localhost.9011 > localhost.64692: Flags [P.], seq 92:178, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 86
17:28:10.098267 IP localhost.64692 > localhost.9011: Flags [.], ack 178, win 12753, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098277 IP localhost.9011 > localhost.64692: Flags [P.], seq 178:192, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 14
17:28:10.098283 IP localhost.64692 > localhost.9011: Flags [.], ack 192, win 12753, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098352 IP localhost.9011 > localhost.64692: Flags [F.], seq 192, ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098369 IP localhost.64692 > localhost.9011: Flags [.], ack 193, win 12753, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.098380 IP localhost.9011 > localhost.64692: Flags [.], ack 373, win 12747, options [nop,nop,TS val 910207639 ecr 910207639], length 0
17:28:10.099183 IP localhost.64692 > localhost.9011: Flags [F.], seq 373, ack 193, win 12753, options [nop,nop,TS val 910207640 ecr 910207639], length 0
17:28:10.099217 IP localhost.9011 > localhost.64692: Flags [.], ack 374, win 12747, options [nop,nop,TS val 910207640 ecr 910207640], length 0

This is a request from a regular Chrome tab that took ~18 seconds.

17:28:27.147218 IP6 localhost.64699 > localhost.9011: Flags [S], seq 1481186887, win 65535, options [mss 16324,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147230 IP6 localhost.9011 > localhost.64699: Flags [R.], seq 0, ack 1481186888, win 0, length 0
17:28:27.147277 IP6 localhost.64700 > localhost.9011: Flags [S], seq 1928824698, win 65535, options [mss 16324,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147287 IP6 localhost.9011 > localhost.64700: Flags [R.], seq 0, ack 1928824699, win 0, length 0
17:28:27.147331 IP6 localhost.64701 > localhost.9011: Flags [S], seq 63463797, win 65535, options [mss 16324,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147340 IP6 localhost.9011 > localhost.64701: Flags [R.], seq 0, ack 63463798, win 0, length 0
17:28:27.147578 IP localhost.64704 > localhost.9011: Flags [S], seq 2185396531, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147602 IP localhost.64705 > localhost.9011: Flags [S], seq 2307844059, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147617 IP localhost.9011 > localhost.64704: Flags [S.], seq 4199967470, ack 2185396532, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 910224643,sackOK,eol], length 0
17:28:27.147627 IP localhost.64706 > localhost.9011: Flags [S], seq 324888549, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 0,sackOK,eol], length 0
17:28:27.147638 IP localhost.9011 > localhost.64705: Flags [S.], seq 1097272416, ack 2307844060, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 910224643,sackOK,eol], length 0
17:28:27.147643 IP localhost.64704 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.147665 IP localhost.9011 > localhost.64706: Flags [S.], seq 837656804, ack 324888550, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224643 ecr 910224643,sackOK,eol], length 0
17:28:27.147669 IP localhost.64705 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.147675 IP localhost.9011 > localhost.64704: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.147681 IP localhost.64706 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.147686 IP localhost.9011 > localhost.64705: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.147691 IP localhost.9011 > localhost.64706: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224643 ecr 910224643], length 0
17:28:27.243730 IP6 localhost.64708 > localhost.9011: Flags [S], seq 4213763930, win 65535, options [mss 16324,nop,wscale 5,nop,nop,TS val 910224733 ecr 0,sackOK,eol], length 0
17:28:27.243748 IP6 localhost.9011 > localhost.64708: Flags [R.], seq 0, ack 4213763931, win 0, length 0
17:28:27.243855 IP localhost.64709 > localhost.9011: Flags [S], seq 1721904940, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224733 ecr 0,sackOK,eol], length 0
17:28:27.243910 IP localhost.9011 > localhost.64709: Flags [S.], seq 2521348026, ack 1721904941, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 910224733 ecr 910224733,sackOK,eol], length 0
17:28:27.243925 IP localhost.64709 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224733 ecr 910224733], length 0
17:28:27.243934 IP localhost.9011 > localhost.64709: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910224733 ecr 910224733], length 0
17:28:27.244093 IP localhost.64709 > localhost.9011: Flags [P.], seq 1:390, ack 1, win 12759, options [nop,nop,TS val 910224733 ecr 910224733], length 389
17:28:27.244108 IP localhost.9011 > localhost.64709: Flags [.], ack 390, win 12747, options [nop,nop,TS val 910224733 ecr 910224733], length 0
17:28:45.693569 IP localhost.64704 > localhost.9011: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910224643], length 0
17:28:45.693596 IP localhost.64705 > localhost.9011: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910224643], length 0
17:28:45.693605 IP localhost.64706 > localhost.9011: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910224643], length 0
17:28:45.693627 IP localhost.9011 > localhost.64704: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693636 IP localhost.9011 > localhost.64705: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693645 IP localhost.9011 > localhost.64706: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693655 IP localhost.64704 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693661 IP localhost.64705 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693666 IP localhost.64706 > localhost.9011: Flags [.], ack 1, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693737 IP localhost.9011 > localhost.64704: Flags [F.], seq 1, ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693766 IP localhost.64704 > localhost.9011: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693862 IP localhost.9011 > localhost.64705: Flags [F.], seq 1, ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693909 IP localhost.64705 > localhost.9011: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693935 IP localhost.9011 > localhost.64706: Flags [F.], seq 1, ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.693949 IP localhost.64706 > localhost.9011: Flags [.], ack 2, win 12759, options [nop,nop,TS val 910243145 ecr 910243145], length 0
17:28:45.694861 IP localhost.9011 > localhost.64709: Flags [P.], seq 1:18, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910224733], length 17
17:28:45.694886 IP localhost.64709 > localhost.9011: Flags [.], ack 18, win 12758, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.694937 IP localhost.9011 > localhost.64709: Flags [P.], seq 18:55, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 37
17:28:45.694958 IP localhost.64709 > localhost.9011: Flags [.], ack 55, win 12757, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.694971 IP localhost.9011 > localhost.64709: Flags [P.], seq 55:92, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 37
17:28:45.694982 IP localhost.64709 > localhost.9011: Flags [.], ack 92, win 12756, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.694997 IP localhost.9011 > localhost.64709: Flags [P.], seq 92:178, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 86
17:28:45.695009 IP localhost.64709 > localhost.9011: Flags [.], ack 178, win 12753, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.695016 IP localhost.9011 > localhost.64709: Flags [P.], seq 178:192, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 14
17:28:45.695020 IP localhost.64709 > localhost.9011: Flags [.], ack 192, win 12753, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.695087 IP localhost.9011 > localhost.64709: Flags [F.], seq 192, ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.695111 IP localhost.64709 > localhost.9011: Flags [.], ack 193, win 12753, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.695120 IP localhost.9011 > localhost.64709: Flags [.], ack 390, win 12747, options [nop,nop,TS val 910243146 ecr 910243146], length 0
17:28:45.696046 IP localhost.64709 > localhost.9011: Flags [F.], seq 390, ack 193, win 12753, options [nop,nop,TS val 910243147 ecr 910243146], length 0
17:28:45.696069 IP localhost.9011 > localhost.64709: Flags [.], ack 391, win 12747, options [nop,nop,TS val 910243147 ecr 910243147], length 0

It looks like Chrome tries IPv6 first, which wsgiref doesn't like. So the connection resets the server sends make sense.

In the case of non-incognito Chrome, it appears as though the client makes several connection attempts. The server resets the first couple attempts, then accepts a few, then using only one of those connections does the client actually send the request. I assume since wsgiref.simple_server is single threaded, the previous connections have to time out before the one that will make the actual request can get handled; thus the delay.

It's interesting to note that even incognito Chrome still experiences a reset, but only it's only retried once, and then works as expected. Firefox and httpie both only establish a single connection that works smoothly.

Questions

  • Why does Chrome try to open so many connections for a single request?
  • What about Chrome's incognito mode causes it to behave more agreeably, here?
  • Is this... a bug? (In either Chrome or wsgiref?)
like image 436
jpk Avatar asked Jan 28 '15 23:01

jpk

1 Answers

tl;dr: Chrome optimizes too aggressively. News at 11.

Turns out this is because of an "optimization" Chrome does to speed up page loads, API interactions, etc.

Chrome has a setting called "Predict network actions to improve page load performance". (It's under Privacy in advanced settings.) When this is enabled, Chrome will preemptively open TCP connections to servers that host resources on the page even before client-side code has reached a point in execution that will tell the browser to make an HTTP request.

In this case, Chrome sees that I'll be making an AJAX request to the CORS server and opens up multiple TCP connections to the server in preparation for additional HTTP requests I might make later on (even though my javascript will only ever make one request to the server). It apparently opens these extra connections before the connection that will actually carry the one HTTP request the javascript will make. This means that for a single-threaded server, those additional connections have to time out before the connection that will carry the request can be serviced. This is the source of the delay.

The "Predict network actions to improve page load performance" setting is enabled by default, and is inactive while incognito (presumably because it leaks the user's behavior to servers that may or may not actually end up getting a request). Disabling it prevents these extra connections from being opened and Chrome behaves identically to Firefox in this scenario.

This makes me wonder how many TCP connections Chrome opens on production servers around the Internet that either go unused or are held open for excessive periods before sending a request. Unused connections wouldn't even show up in access logs because no HTTP request is made, so it would be hard to gauge how much extra load Chrome users create. In my opinion, this behavior is harmful. First, because it attempts to improve client performance (which is admirable), but does so at the expense of server operators (which is not). And second, because (as is obviated by it being disabled in incognito) has negative privacy implications.

like image 110
jpk Avatar answered Oct 18 '22 05:10

jpk
Sign in to Comment

Related questions

Sending file direct from browser to S3 but changing file name
best way to sort list based on key in nested object array in java script
Overriding AngularJs Service
Inject a JavaScript code in Webview iOS
Why :Math.floor(2e+21) != ~~(2e+21)
Displaying CSV Headers using PapaParse Plugin
HTML5 JavaScript Download attribute
How to set right date format for editable-date
JSON.parse UTF-8 string
Nodejs - promises, unhandled termination and memory leak
How to manually update AngularJS view using ControllerAs syntax?
Chrome not detecting image sizes
How do i load my local json file just using JavaScript
Is the Access-Control-Allow-Origin CORS header required when doing a preflight request?
How to hide a highcharts pie slice programatically
How to use webpack for development without webpack dev server?
Highcharts labels cut off
NodeJS http module: what is requestListener?
TypeError: $(...).selectize is not a function
Sending an Error Object from a spawned child-process over an IPC-channel

Donate For Us

If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!