Client hangs after triggering a `data request overlap from client` error because no response is sent, but the connection remains open

[posita]

UPDATE: I believe I have found the cause. See #363 (comment) for more details.

I can reliably reproduce deadlocks within Engine.IO when serving multiple concurrent requests on a single session over a UNIX socket. Here's how to run:

% git clone https://github.com/posita/txsocketio.git .../txsocketio
% (cd .../txsocketio && git co 548e989022b28dc302280940431c000f44b1f58f )
% ( cd .../txsocketio/integrations/node && npm install )
...

% # SHELL # 1 - run local Engine.IO instance serving over UNIX domain socket
% ( cd .../txsocketio/integrations/node && DEBUG=\* npm start )
...

% # SHELL # 2 - run tests to connect to local Engine.IO instance
% ( cd .../txsocketio/integrations/node && TEST_DEADLOCK=1 tox -e py27-twisted_15_4-ssl_yes tests.integration_deadlock )
...

You may have to run the tests in SHELL # 2 several times before you observe the deadlock. You'll know you've hit it when the test doesn't resolve within a few seconds.

This is what the failure looks like:

% # SHELL # 1
% ( cd .../txsocketio/integrations/node && DEBUG=\* npm start )
...
[20:06:40.446] [LOG]     engine intercepting request for path "/engine.io/" +46s
[20:06:40.446] [LOG]     engine handling "GET" http request "/engine.io/?transport=polling" +0ms
[20:06:40.447] [LOG]     engine handshaking client "2hS896Vuh-koQ3HHAAAE" +1ms
[20:06:40.448] [LOG]     engine:socket sending packet "open" ({"sid":"2hS896Vuh-koQ3HHAAAE","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}) +1ms
[20:06:40.448] [LOG]     engine:polling setting request +0ms
[20:06:40.449] [LOG]     engine:socket flushing buffer to transport +1ms
[20:06:40.449] [LOG]     engine:polling writing "       �0{"sid":"2hS896Vuh-koQ3HHAAAE","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +0ms
[20:06:40.451] [LOG]     engine:socket executing batch send callback +2ms
[20:06:40.452] [LOG]     engine:socket sending packet "message" (Hello!) +1ms
[20:06:40.491] [LOG]     engine intercepting request for path "/engine.io/" +39ms
[20:06:40.491] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=2hS896Vuh-koQ3HHAAAE" +0ms
[20:06:40.491] [LOG]     engine setting new request for existing client +0ms
[20:06:40.492] [LOG]     engine:polling received "�2probe" +1ms
[20:06:40.492] [LOG]     engine:socket packet +0ms
[20:06:40.492] [LOG]     engine:socket got ping +0ms
[20:06:40.492] [LOG]     engine:socket sending packet "pong" (undefined) +0ms
[20:06:40.493] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[20:06:40.493] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=2hS896Vuh-koQ3HHAAAE" +0ms
[20:06:40.493] [LOG]     engine setting new request for existing client +0ms
[20:06:40.494] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[20:06:40.494] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=2hS896Vuh-koQ3HHAAAE" +0ms
[20:06:40.494] [LOG]     engine setting new request for existing client +0ms
[20:06:40.495] [LOG]     engine:socket transport error +0ms
[20:06:40.497] [LOG]     engine:polling received "�2probe" +3ms
[20:06:40.497] [LOG]     engine:socket packet received with closed socket +0ms
...

Note the hung Deferred at index 0:

% # SHELL # 2
% ( cd .../txsocketio/integrations/node && TEST_DEADLOCK=1 tox -e py27-twisted_15_4-ssl_yes tests.integration_deadlock )
...
================================================================
>>> FAIL: at least one of the requests is hung after 100 seconds! <<<
post_deferreds[0]: <Deferred at 0x102988830 waiting on Deferred at 0x1029a4878>
post_deferreds[1]: <Deferred at 0x1029a4560 current result: <twisted.web._newclient.Response object at 0x10297fc90>>
post_deferreds[2]: <Deferred at 0x1029bccb0 current result: <twisted.web._newclient.Response object at 0x1028f4310>>
================================================================
...

Compare that to what happens when everything occasionally works as expected:

% # SHELL # 1
% ( cd .../txsocketio/integrations/node && DEBUG=\* npm start )
...
[19:59:32.080] [LOG]     engine intercepting request for path "/engine.io/" +0ms
[19:59:32.084] [LOG]     engine handling "GET" http request "/engine.io/?transport=polling" +6ms
[19:59:32.088] [LOG]     engine handshaking client "G4Db-G6cmltuPbeYAAAA" +4ms
[19:59:32.090] [LOG]     engine:socket sending packet "open" ({"sid":"G4Db-G6cmltuPbeYAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}) +2ms
[19:59:32.091] [LOG]     engine:polling setting request +1ms
[19:59:32.092] [LOG]     engine:socket flushing buffer to transport +1ms
[19:59:32.094] [LOG]     engine:polling writing "       �0{"sid":"G4Db-G6cmltuPbeYAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +2ms
[19:59:32.100] [LOG]     engine:socket executing batch send callback +6ms
[19:59:32.101] [LOG]     engine:socket sending packet "message" (Hello!) +1ms
[19:59:32.153] [LOG]     engine intercepting request for path "/engine.io/" +52ms
[19:59:32.154] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=G4Db-G6cmltuPbeYAAAA" +1ms
[19:59:32.155] [LOG]     engine setting new request for existing client +1ms
[19:59:32.156] [LOG]     engine:polling received "�2probe" +1ms
[19:59:32.158] [LOG]     engine:socket packet +2ms
[19:59:32.159] [LOG]     engine:socket got ping +0ms
[19:59:32.159] [LOG]     engine:socket sending packet "pong" (undefined) +1ms
[19:59:32.161] [LOG]     engine intercepting request for path "/engine.io/" +2ms
[19:59:32.161] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=G4Db-G6cmltuPbeYAAAA" +0ms
[19:59:32.162] [LOG]     engine setting new request for existing client +1ms
[19:59:32.162] [LOG]     engine:polling received "�2probe" +0ms
[19:59:32.163] [LOG]     engine:socket packet +1ms
[19:59:32.163] [LOG]     engine:socket got ping +0ms
[19:59:32.164] [LOG]     engine:socket sending packet "pong" (undefined) +1ms
[19:59:32.164] [LOG]     engine intercepting request for path "/engine.io/" +0ms
[19:59:32.164] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=G4Db-G6cmltuPbeYAAAA" +0ms
[19:59:32.165] [LOG]     engine setting new request for existing client +1ms
[19:59:32.165] [LOG]     engine:polling received "�2probe" +0ms
[19:59:32.166] [LOG]     engine:socket packet +1ms
[19:59:32.166] [LOG]     engine:socket got ping +0ms
[19:59:32.166] [LOG]     engine:socket sending packet "pong" (undefined) +0ms

% # SHELL # 2
% ( cd .../txsocketio/integrations/node && TEST_DEADLOCK=1 tox -e py27-twisted_15_4-ssl_yes tests.integration_deadlock )
...
================================================================
All requests resolved
post_deferreds[0]: <Deferred at 0x10b000830 current result: <twisted.web._newclient.Response object at 0x10b0168d0>>
post_deferreds[1]: <Deferred at 0x10b01a560 current result: <twisted.web._newclient.Response object at 0x10b004450>>
post_deferreds[2]: <Deferred at 0x10b033cb0 current result: <twisted.web._newclient.Response object at 0x10b016ad0>>
================================================================
...

I noticed this while working on my own client code (which is why the test uses Twisted python), but the deadlock appears to be on the server side. Note that in the failing case, the server has log entries for all three POSTs, but does not respond (and does not send the corresponding pong packets) for all three. I'm guessing one could (easily?) rewrite the tests using engine.io-client and likely achieve the same result (but see below). UPDATE: Without substantial tinkering, I'm not sure how one would implement this test using the engine.io-client, since it appears to be implemented solely in terms of IP connections rather than basic sockets. (Unless I'm missing something?)

The server instance used in the test is stupid simple. It is essentially:

var http = require('http');
var path = require('path');
var engine_io = require('engine.io');
require('console-stamp')(console, { pattern: 'HH:MM:ss.l' });
var app = http.createServer();

process.on('SIGINT', function () {
    app.close();
    process.exit();
});

var eio = engine_io(app);
var sock_path = path.join(__dirname, 'http.sock');
app.listen(sock_path);

(I've actually reduced the code to the exactly the above, and am still able to reproduce the issue.)

Also, this isn't dependent on sending ping packets packets. If one changes the packet data sent from the client from b'\x00\x06\xff2probe' to (e.g.) b'\x00\x06\xff4abcde', the deadlock will still (often) occur.

In the interest of some isolation, I attempted to reproduce the issue using curl from the command line, but am as-of-yet unsuccessful in triggering the deadlock using something like the following:

(
    echo -n $'\x00\x06\xff2probe' >|data.bin
    for (( i=0; i < 10; ++i )) ; do
        (
            sid="$( python -c 'import sys, urllib ; print(urllib.urlencode({ "sid": sys.argv[1].strip() }))' "$( curl --max-time 1 --verbose --unix-socket ./integrations/node/http.sock 'http:/engine.io/?transport=polling' 2>&1 | grep '^< Set-Cookie: io=' | sed '-es%^.*: io=%%' )" )"
            f() { curl --data-binary \@data.bin --header 'Content-Type: application/octet-stream' --max-time 10 --request POST --unix-socket ./integrations/node/http.sock "http:/engine.io/?transport=polling&${sid}" || echo '>>>>>>>> TIMED OUT! <<<<<<<<' }
            f & f & f & f & f &
        ) &
        sleep 1
    done
    sleep 10
    rm -f data.bin
)

I suspect this is because the average interval between POSTs is substantially larger when coming from my command line script (typically > 10 ms) versus those from my Twisted python test (typically around 1-3 ms). UPDATE: this isn't quite true. Once the loop gets going, I've observed split times on par with my Twisted version, but on average they are still higher. One difference might be that all connections (while separate) are coming from the same process in the Twisted version, whereas they are all different curl processes in the shell version? Another difference might be the time between the GET method to acquire the session ID and the first POST? UPDATE to the UPDATE: If I create a delay of 10 ms between requests from within my Twisted version, I don't get any deadlocks on my machine.

[posita]

Okay, I did some more experimenting. I have been unable to produce this with a rudimentary JavaScript client. 😕

I tried inserting socat as a "sniffer" for each separate POST connection by doing something like this:

for (( i=0 ; i < 5 ; ++i)) ; do
    socat 2>|"socat-${i}.txt" \
        -t10 -v -x \
        "UNIX-LISTEN:integrations/node/http-snoop-${i}.sock,fork,mode=750,reuseaddr,unlink-early" \
        UNIX-CONNECT:integrations/node/http.sock &
done

Then I had the POSTers each connect to a different respective socket monitored by socat.¹

I still got a deadlock with my Twisted python version (note index 2):

...
================================================================
>>> FAIL: at least one of the requests is hung after 100 seconds! <<<
post_deferreds[0]: <Deferred at 0x110d813f8 current result: <twisted.web._newclient.Response object at 0x110d228d0>>
post_deferreds[1]: <Deferred at 0x110d8d710 current result: <twisted.web._newclient.Response object at 0x110dc5790>>
post_deferreds[2]: <Deferred at 0x110d94ab8 waiting on Deferred at 0x110d8d908>
post_deferreds[3]: <Deferred at 0x110d9ae60 current result: <twisted.web._newclient.Response object at 0x110dc5c10>>
post_deferreds[4]: <Deferred at 0x110da9248 current result: <twisted.web._newclient.Response object at 0x110da0150>>
================================================================
...

Server logs from Twisted python clients:

...
[13:00:56.068] [LOG]     engine intercepting request for path "/engine.io/" +2m
[13:00:56.068] [LOG]     engine handling "GET" http request "/engine.io/?transport=polling" +1ms
[13:00:56.068] [LOG]     engine handshaking client "i5IEMr13XT65gRsIAAAF" +0ms
[13:00:56.069] [LOG]     engine:socket sending packet "open" ({"sid":"i5IEMr13XT65gRsIAAAF","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}) +1ms
[13:00:56.069] [LOG]     engine:polling setting request +0ms
[13:00:56.069] [LOG]     engine:socket flushing buffer to transport +0ms
[13:00:56.070] [LOG]     engine:polling writing "       �0{"sid":"i5IEMr13XT65gRsIAAAF","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +1ms
[13:00:56.070] [LOG]     engine:socket executing batch send callback +0ms
[13:00:56.130] [LOG]     engine intercepting request for path "/engine.io/" +60ms
[13:00:56.130] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=i5IEMr13XT65gRsIAAAF" +0ms
[13:00:56.132] [LOG]     engine setting new request for existing client +1ms
[13:00:56.135] [LOG]     engine intercepting request for path "/engine.io/" +3ms
[13:00:56.138] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=i5IEMr13XT65gRsIAAAF" +4ms
[13:00:56.139] [LOG]     engine setting new request for existing client +1ms
[13:00:56.140] [LOG]     engine:socket transport error +1ms
[13:00:56.140] [LOG]     engine:polling received "�2probe" +0ms
[13:00:56.140] [LOG]     engine:socket packet received with closed socket +0ms
[13:00:56.141] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[13:00:56.143] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=i5IEMr13XT65gRsIAAAF" +2ms
[13:00:56.144] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[13:00:56.144] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=i5IEMr13XT65gRsIAAAF" +0ms
[13:00:56.145] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[13:00:56.147] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=i5IEMr13XT65gRsIAAAF" +2ms
...

socat sniffer output from Twisted python clients (note that nothing comes back over the wire from Engine.IO for index 2):

% # ================================================================
% cat socat-0.txt
> 2015/11/13 13:00:56.126765  length=287 from=0 to=286
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 69 35 49 45 4d 72 31 33 58  ng&sid=i5IEMr13X
 54 36 35 67 52 73 49 41 41 41 46 20 48 54 54 50  T65gRsIAAAF HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 0d 0a                                            ..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6a 73 6f 6e 0d 0a                    ion/json..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 48 6f 73 74 3a 20 2e 25 32 46 69 6e 74 65 67 72  Host: .%2Fintegr
 61 74 69 6f 6e 73 25 32 46 6e 6f 64 65 25 32 46  ations%2Fnode%2F
 68 74 74 70 2d 73 6e 6f 6f 70 2d 30 2e 73 6f 63  http-snoop-0.soc
 6b 3a 38 30 0d 0a                                k:80..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 0d 0a                                            ..
--
> 2015/11/13 13:00:56.139455  length=9 from=287 to=295
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 13:00:56.141060  length=190 from=0 to=189
 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d  HTTP/1.1 200 OK.
 0a                                               .
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 74 65  Content-Type: te
 78 74 2f 68 74 6d 6c 0d 0a                       xt/html..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 32 0d 0a                                         2..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 69 6f 3d 69  Set-Cookie: io=i
 35 49 45 4d 72 31 33 58 54 36 35 67 52 73 49 41  5IEMr13XT65gRsIA
 41 41 46 0d 0a                                   AAF..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 31 3a 30 30 3a 35 36 20  v 2015 21:00:56
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 0d 0a                                            ..
 6f 6b                                            ok
--
% # ================================================================
% cat socat-1.txt
> 2015/11/13 13:00:56.129741  length=287 from=0 to=286
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 69 35 49 45 4d 72 31 33 58  ng&sid=i5IEMr13X
 54 36 35 67 52 73 49 41 41 41 46 20 48 54 54 50  T65gRsIAAAF HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 0d 0a                                            ..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6a 73 6f 6e 0d 0a                    ion/json..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 48 6f 73 74 3a 20 2e 25 32 46 69 6e 74 65 67 72  Host: .%2Fintegr
 61 74 69 6f 6e 73 25 32 46 6e 6f 64 65 25 32 46  ations%2Fnode%2F
 68 74 74 70 2d 73 6e 6f 6f 70 2d 31 2e 73 6f 63  http-snoop-1.soc
 6b 3a 38 30 0d 0a                                k:80..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 0d 0a                                            ..
--
> 2015/11/13 13:00:56.139738  length=9 from=287 to=295
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 13:00:56.146527  length=228 from=0 to=227
 48 54 54 50 2f 31 2e 31 20 34 30 30 20 42 61 64  HTTP/1.1 400 Bad
 20 52 65 71 75 65 73 74 0d 0a                     Request..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 0d 0a  plication/json..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 31 3a 30 30 3a 35 36 20  v 2015 21:00:56
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 54 72 61 6e 73 66 65 72 2d 45 6e 63 6f 64 69 6e  Transfer-Encodin
 67 3a 20 63 68 75 6e 6b 65 64 0d 0a              g: chunked..
 0d 0a                                            ..
 32 39 0d 0a                                      29..
 7b 22 63 6f 64 65 22 3a 31 2c 22 6d 65 73 73 61  {"code":1,"messa
 67 65 22 3a 22 53 65 73 73 69 6f 6e 20 49 44 20  ge":"Session ID
 75 6e 6b 6e 6f 77 6e 22 7d 0d 0a                 unknown"}..
 30 0d 0a                                         0..
 0d 0a                                            ..
--
% # ================================================================
% cat socat-2.txt # <-- this is the deadlocked one
> 2015/11/13 13:00:56.126726  length=287 from=0 to=286
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 69 35 49 45 4d 72 31 33 58  ng&sid=i5IEMr13X
 54 36 35 67 52 73 49 41 41 41 46 20 48 54 54 50  T65gRsIAAAF HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 0d 0a                                            ..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6a 73 6f 6e 0d 0a                    ion/json..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 48 6f 73 74 3a 20 2e 25 32 46 69 6e 74 65 67 72  Host: .%2Fintegr
 61 74 69 6f 6e 73 25 32 46 6e 6f 64 65 25 32 46  ations%2Fnode%2F
 68 74 74 70 2d 73 6e 6f 6f 70 2d 32 2e 73 6f 63  http-snoop-2.soc
 6b 3a 38 30 0d 0a                                k:80..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 0d 0a                                            ..
--
> 2015/11/13 13:00:56.139332  length=9 from=287 to=295
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
% # ================================================================
% cat socat-3.txt
> 2015/11/13 13:00:56.133296  length=287 from=0 to=286
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 69 35 49 45 4d 72 31 33 58  ng&sid=i5IEMr13X
 54 36 35 67 52 73 49 41 41 41 46 20 48 54 54 50  T65gRsIAAAF HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 0d 0a                                            ..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6a 73 6f 6e 0d 0a                    ion/json..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 48 6f 73 74 3a 20 2e 25 32 46 69 6e 74 65 67 72  Host: .%2Fintegr
 61 74 69 6f 6e 73 25 32 46 6e 6f 64 65 25 32 46  ations%2Fnode%2F
 68 74 74 70 2d 73 6e 6f 6f 70 2d 33 2e 73 6f 63  http-snoop-3.soc
 6b 3a 38 30 0d 0a                                k:80..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 0d 0a                                            ..
--
> 2015/11/13 13:00:56.139181  length=9 from=287 to=295
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 13:00:56.148496  length=228 from=0 to=227
 48 54 54 50 2f 31 2e 31 20 34 30 30 20 42 61 64  HTTP/1.1 400 Bad
 20 52 65 71 75 65 73 74 0d 0a                     Request..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 0d 0a  plication/json..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 31 3a 30 30 3a 35 36 20  v 2015 21:00:56
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 54 72 61 6e 73 66 65 72 2d 45 6e 63 6f 64 69 6e  Transfer-Encodin
 67 3a 20 63 68 75 6e 6b 65 64 0d 0a              g: chunked..
 0d 0a                                            ..
 32 39 0d 0a                                      29..
 7b 22 63 6f 64 65 22 3a 31 2c 22 6d 65 73 73 61  {"code":1,"messa
 67 65 22 3a 22 53 65 73 73 69 6f 6e 20 49 44 20  ge":"Session ID
 75 6e 6b 6e 6f 77 6e 22 7d 0d 0a                 unknown"}..
 30 0d 0a                                         0..
 0d 0a                                            ..
--
% # ================================================================
% cat socat-4.txt
> 2015/11/13 13:00:56.127379  length=287 from=0 to=286
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 69 35 49 45 4d 72 31 33 58  ng&sid=i5IEMr13X
 54 36 35 67 52 73 49 41 41 41 46 20 48 54 54 50  T65gRsIAAAF HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 0d 0a                                            ..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6a 73 6f 6e 0d 0a                    ion/json..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 48 6f 73 74 3a 20 2e 25 32 46 69 6e 74 65 67 72  Host: .%2Fintegr
 61 74 69 6f 6e 73 25 32 46 6e 6f 64 65 25 32 46  ations%2Fnode%2F
 68 74 74 70 2d 73 6e 6f 6f 70 2d 34 2e 73 6f 63  http-snoop-4.soc
 6b 3a 38 30 0d 0a                                k:80..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 0d 0a                                            ..
--
> 2015/11/13 13:00:56.139469  length=9 from=287 to=295
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 13:00:56.144137  length=228 from=0 to=227
 48 54 54 50 2f 31 2e 31 20 34 30 30 20 42 61 64  HTTP/1.1 400 Bad
 20 52 65 71 75 65 73 74 0d 0a                     Request..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 0d 0a  plication/json..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 31 3a 30 30 3a 35 36 20  v 2015 21:00:56
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 54 72 61 6e 73 66 65 72 2d 45 6e 63 6f 64 69 6e  Transfer-Encodin
 67 3a 20 63 68 75 6e 6b 65 64 0d 0a              g: chunked..
 0d 0a                                            ..
 32 39 0d 0a                                      29..
 7b 22 63 6f 64 65 22 3a 31 2c 22 6d 65 73 73 61  {"code":1,"messa
 67 65 22 3a 22 53 65 73 73 69 6f 6e 20 49 44 20  ge":"Session ID
 75 6e 6b 6e 6f 77 6e 22 7d 0d 0a                 unknown"}..
 30 0d 0a                                         0..
 0d 0a                                            ..
--

Compare this to when I run the JavaScript client version (ran with ( cd .../txsocketio/deadlock && npm install && npm start )).

Server logs from JavaScript clients:

...
[12:58:39.255] [LOG]     engine intercepting request for path "/engine.io/" +7m
[12:58:39.255] [LOG]     engine handling "GET" http request "/engine.io/?transport=polling" +0ms
[12:58:39.257] [LOG]     engine handshaking client "Qr_EvRVelef7YMRDAAAE" +2ms
[12:58:39.257] [LOG]     engine:socket sending packet "open" ({"sid":"Qr_EvRVelef7YMRDAAAE","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}) +0ms
[12:58:39.257] [LOG]     engine:polling setting request +0ms
[12:58:39.258] [LOG]     engine:socket flushing buffer to transport +1ms
[12:58:39.258] [LOG]     engine:polling writing "       �0{"sid":"Qr_EvRVelef7YMRDAAAE","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +0ms
[12:58:39.258] [LOG]     engine:socket executing batch send callback +0ms
[12:58:39.328] [LOG]     engine intercepting request for path "/engine.io/" +70ms
[12:58:39.329] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=Qr_EvRVelef7YMRDAAAE" +1ms
[12:58:39.329] [LOG]     engine setting new request for existing client +0ms
[12:58:39.330] [LOG]     engine:polling received "�2probe" +1ms
[12:58:39.330] [LOG]     engine:socket packet +0ms
[12:58:39.330] [LOG]     engine:socket got ping +0ms
[12:58:39.331] [LOG]     engine:socket sending packet "pong" (undefined) +1ms
[12:58:39.332] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[12:58:39.332] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=Qr_EvRVelef7YMRDAAAE" +0ms
[12:58:39.332] [LOG]     engine setting new request for existing client +0ms
[12:58:39.333] [LOG]     engine:polling received "�2probe" +1ms
[12:58:39.333] [LOG]     engine:socket packet +0ms
[12:58:39.334] [LOG]     engine:socket got ping +1ms
[12:58:39.334] [LOG]     engine:socket sending packet "pong" (undefined) +0ms
[12:58:39.335] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[12:58:39.335] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=Qr_EvRVelef7YMRDAAAE" +0ms
[12:58:39.335] [LOG]     engine setting new request for existing client +0ms
[12:58:39.336] [LOG]     engine:polling received "�2probe" +1ms
[12:58:39.336] [LOG]     engine:socket packet +0ms
[12:58:39.336] [LOG]     engine:socket got ping +0ms
[12:58:39.337] [LOG]     engine:socket sending packet "pong" (undefined) +1ms
[12:58:39.342] [LOG]     engine intercepting request for path "/engine.io/" +5ms
[12:58:39.343] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=Qr_EvRVelef7YMRDAAAE" +0ms
[12:58:39.343] [LOG]     engine setting new request for existing client +1ms
[12:58:39.343] [LOG]     engine:polling received "�2probe" +0ms
[12:58:39.343] [LOG]     engine:socket packet +0ms
[12:58:39.344] [LOG]     engine:socket got ping +1ms
[12:58:39.344] [LOG]     engine:socket sending packet "pong" (undefined) +0ms
[12:58:39.345] [LOG]     engine intercepting request for path "/engine.io/" +1ms
[12:58:39.345] [LOG]     engine handling "POST" http request "/engine.io/?transport=polling&sid=Qr_EvRVelef7YMRDAAAE" +0ms
[12:58:39.346] [LOG]     engine setting new request for existing client +1ms
[12:58:39.346] [LOG]     engine:polling received "�2probe" +0ms
[12:58:39.346] [LOG]     engine:socket packet +0ms
[12:58:39.347] [LOG]     engine:socket got ping +1ms
[12:58:39.353] [LOG]     engine:socket sending packet "pong" (undefined) +6ms
...

socat sniffer output from JavaScript clients (truncated, they're pretty much all like this):

...
% # ================================================================
% cat socat-1.txt
> 2015/11/13 12:58:39.325950  length=304 from=0 to=303
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 51 72 5f 45 76 52 56 65 6c  ng&sid=Qr_EvRVel
 65 66 37 59 4d 52 44 41 41 41 45 20 48 54 54 50  ef7YMRDAAAE HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f  ,application/jso
 6e 0d 0a                                         n..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 68 6f 73 74 3a 20 2f 55 73 65 72 73 2f 6d 61 74  host: /Users/mat
 74 2f 44 6f 63 75 6d 65 6e 74 73 2f 64 65 76 2f  t/Documents/dev/
 74 78 73 6f 63 6b 65 74 69 6f 2f 69 6e 74 65 67  txsocketio/integ
 72 61 74 69 6f 6e 73 2f 6e 6f 64 65 2f 68 74 74  rations/node/htt
 70 2d 73 6e 6f 6f 70 2d 31 2e 73 6f 63 6b 0d 0a  p-snoop-1.sock..
 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 3a 20  content-length:
 39 0d 0a                                         9..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 0d 0a                                            ..
--
> 2015/11/13 12:58:39.330303  length=9 from=304 to=312
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 12:58:39.344884  length=190 from=0 to=189
 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d  HTTP/1.1 200 OK.
 0a                                               .
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 74 65  Content-Type: te
 78 74 2f 68 74 6d 6c 0d 0a                       xt/html..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 32 0d 0a                                         2..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 69 6f 3d 51  Set-Cookie: io=Q
 72 5f 45 76 52 56 65 6c 65 66 37 59 4d 52 44 41  r_EvRVelef7YMRDA
 41 41 45 0d 0a                                   AAE..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 30 3a 35 38 3a 33 39 20  v 2015 20:58:39
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 0d 0a                                            ..
 6f 6b                                            ok
--
% # ================================================================
% cat socat-2.txt
> 2015/11/13 12:58:39.326715  length=313 from=0 to=312
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 51 72 5f 45 76 52 56 65 6c  ng&sid=Qr_EvRVel
 65 66 37 59 4d 52 44 41 41 41 45 20 48 54 54 50  ef7YMRDAAAE HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 41 63 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74  Accept: applicat
 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 65 61 6d  ion/octet-stream
 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f  ,application/jso
 6e 0d 0a                                         n..
 41 63 63 65 70 74 2d 43 68 61 72 73 65 74 3a 20  Accept-Charset:
 55 54 46 2d 38 0d 0a                             UTF-8..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 68 6f 73 74 3a 20 2f 55 73 65 72 73 2f 6d 61 74  host: /Users/mat
 74 2f 44 6f 63 75 6d 65 6e 74 73 2f 64 65 76 2f  t/Documents/dev/
 74 78 73 6f 63 6b 65 74 69 6f 2f 69 6e 74 65 67  txsocketio/integ
 72 61 74 69 6f 6e 73 2f 6e 6f 64 65 2f 68 74 74  rations/node/htt
 70 2d 73 6e 6f 6f 70 2d 32 2e 73 6f 63 6b 0d 0a  p-snoop-2.sock..
 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 3a 20  content-length:
 39 0d 0a                                         9..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 0d 0a                                            ..
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 12:58:39.336700  length=190 from=0 to=189
 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d  HTTP/1.1 200 OK.
 0a                                               .
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 74 65  Content-Type: te
 78 74 2f 68 74 6d 6c 0d 0a                       xt/html..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 32 0d 0a                                         2..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 69 6f 3d 51  Set-Cookie: io=Q
 72 5f 45 76 52 56 65 6c 65 66 37 59 4d 52 44 41  r_EvRVelef7YMRDA
 41 41 45 0d 0a                                   AAE..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 30 3a 35 38 3a 33 39 20  v 2015 20:58:39
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73  Connection: clos
 65 0d 0a                                         e..
 0d 0a                                            ..
 6f 6b                                            ok
--
...

The curl version mirrors the JavaScript version.

socat sniffer output from curl clients (truncated, they're pretty much all like this):

...
% # ================================================================
% cat socat-2.txt
> 2015/11/13 13:22:50.870300  length=190 from=0 to=189
 50 4f 53 54 20 2f 65 6e 67 69 6e 65 2e 69 6f 2f  POST /engine.io/
 3f 74 72 61 6e 73 70 6f 72 74 3d 70 6f 6c 6c 69  ?transport=polli
 6e 67 26 73 69 64 3d 75 6d 67 56 67 59 54 68 78  ng&sid=umgVgYThx
 42 78 46 4e 74 42 4e 41 41 41 53 20 48 54 54 50  BxFNtBNAAAS HTTP
 2f 31 2e 31 0d 0a                                /1.1..
 48 6f 73 74 3a 20 68 74 74 70 0d 0a              Host: http..
 55 73 65 72 2d 41 67 65 6e 74 3a 20 63 75 72 6c  User-Agent: curl
 2f 37 2e 34 35 2e 30 0d 0a                       /7.45.0..
 41 63 63 65 70 74 3a 20 2a 2f 2a 0d 0a           Accept: */*..
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70  Content-Type: ap
 70 6c 69 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d  plication/octet-
 73 74 72 65 61 6d 0d 0a                          stream..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 39 0d 0a                                         9..
 0d 0a                                            ..
 00 06 ff 32 70 72 6f 62 65                       ...2probe
--
< 2015/11/13 13:22:50.875725  length=195 from=0 to=194
 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d  HTTP/1.1 200 OK.
 0a                                               .
 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 74 65  Content-Type: te
 78 74 2f 68 74 6d 6c 0d 0a                       xt/html..
 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20  Content-Length:
 32 0d 0a                                         2..
 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41  Access-Control-A
 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a  llow-Origin: *..
 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 69 6f 3d 75  Set-Cookie: io=u
 6d 67 56 67 59 54 68 78 42 78 46 4e 74 42 4e 41  mgVgYThxBxFNtBNA
 41 41 53 0d 0a                                   AAS..
 44 61 74 65 3a 20 46 72 69 2c 20 31 33 20 4e 6f  Date: Fri, 13 No
 76 20 32 30 31 35 20 32 31 3a 32 32 3a 35 30 20  v 2015 21:22:50
 47 4d 54 0d 0a                                   GMT..
 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 6b 65 65 70  Connection: keep
 2d 61 6c 69 76 65 0d 0a                          -alive..
 0d 0a                                            ..
 6f 6b                                            ok
--
...

¹ These are the local modifications I made to each test client to enable this:

diff --git a/deadlock/server.js b/deadlock/server.js
index c0d79f4..1822e03 100644
--- a/deadlock/server.js
+++ b/deadlock/server.js
@@ -41,13 +41,11 @@ request(req_options, function (error, response, body) {
     console.log('sid: ' + sid);
     req_options.url += '&sid=' + sid;
     req_options.headers['Content-Type'] = 'application/octet-stream';
-    req_options.method = 'POST';
-    req_options.body = packet_array;
     console.log('start');

     for (var i = 0; i < num_packets; ++i) {
         (function (i) {
-            request(req_options, function (error, response, body) {
+            request({ url: req_options.url.replace('http.sock', 'http-snoop-' + i + '.sock'), headers: req_options.headers, method: 'POST', body: packet_array }, function (error, response, body) {
                 console.log('end ' + i + ': ' + body);
             });
         })(i);
diff --git a/tests/integration_deadlock.py b/tests/integration_deadlock.py
index 9f6ac83..58b7d64 100644
--- a/tests/integration_deadlock.py
+++ b/tests/integration_deadlock.py
@@ -91,8 +91,8 @@ class TestDeadlock(t_unittest.TestCase):
             b'Content-Type':   [ b'application/octet-stream' ],
         })

-        def _sendpacket(_session, _payload):
-            post_url_bytes = url_bytes + b'&' + parse.urlencode({ b'sid': _session })
+        def _sendpacket(_i, _session, _payload):
+            post_url_bytes = url_bytes.replace(b'http.sock', b'http-snoop-{}.sock'.format(i)) + b'&' + parse.urlencode({ b'sid': _session })
             body_producer = t_client.FileBodyProducer(io.BytesIO(_payload))
             d = agent.request(b'POST', post_url_bytes, post_headers, body_producer)
             d.addErrback(lambda _: [ _ ] if isinstance(_, t_failure.Failure) else _)
@@ -105,11 +105,11 @@ class TestDeadlock(t_unittest.TestCase):

         # In my testing, this needs to loop at least 3 times to reliably
         # trigger the deadlock
-        for _ in range(5):
+        for i in range(5):
             # One will not likely observe the deadlock after uncommenting
             # the following (which will wait 10+ ms between POST attempts)
             # yield t_task.deferLater(reactor, 10 / 1000, lambda: None)
-            post_deferreds.append(_sendpacket(session, packet_raw))
+            post_deferreds.append(_sendpacket(i, session, packet_raw))

         def _printpostdeferreds(_summary):
             print('================================================================', file=sys.stderr)

My modified curl command was as follows:

(
    echo -n $'\x00\x06\xff2probe' >|data.bin
    for (( i=0; i < 1; ++i )) ; do
        (
            sid="$( python -c 'import sys, urllib ; print(urllib.urlencode({ "sid": sys.argv[1].strip() }))' "$( curl --max-time 1 --verbose --unix-socket ./integrations/node/http.sock 'http:/engine.io/?transport=polling' 2>&1 | grep '^< Set-Cookie: io=' | sed '-es%^.*: io=%%' )" )"
            f() { curl --data-binary \@data.bin --header 'Content-Type: application/octet-stream' --max-time 10 --request POST --unix-socket "./integrations/node/http-snoop-${1}.sock" "http:/engine.io/?transport=polling&${sid}" || echo '>>>>>>>> TIMED OUT! <<<<<<<<' }
            f 0 & f 1 & f 2 & f 3 & f 4 &
        ) &
        sleep 1
    done
    sleep 10
    rm -f data.bin
)

These are primarily notes to myself, since I haven't checked in these changes.

[posita]

One thing to note is that with the Twisted version, the POST data from each connection comes in practically right on top of each other, irrespective of when the connection was made. I haven't observed this with the JavaScript or curl versions.

[posita]

It looks like the hung connection is resulting in Socket.onError being called, but the default logs don't seem to indicate why. I printed out err and got this (apparently from here):

[14:46:10.801] [LOG]     engine:socket Error: data request overlap from client
    at XHR.Transport.onError (/.../txsocketio/integrations/node/node_modules/engine.io/lib/transport.js:74:15)
    at XHR.Polling.onDataRequest (/.../txsocketio/integrations/node/node_modules/engine.io/lib/transports/polling.js:115:10)
    at XHR.Polling.onRequest (/.../txsocketio/integrations/node/node_modules/engine.io/lib/transports/polling.js:55:10)
    at XHR.onRequest (/.../txsocketio/integrations/node/node_modules/engine.io/lib/transports/polling-xhr.js:47:33)
    at /.../txsocketio/integrations/node/node_modules/engine.io/lib/server.js:182:46
    at Server.verify (/.../txsocketio/integrations/node/node_modules/engine.io/lib/server.js:130:3)
    at Server.handleRequest (/.../txsocketio/integrations/node/node_modules/engine.io/lib/server.js:174:8)
    at Server.<anonymous> (/.../txsocketio/integrations/node/node_modules/engine.io/lib/server.js:366:12)
    at Server.emit (events.js:110:17)
    at HTTPParser.parserOnIncoming [as onIncoming] (_http_server.js:491:12) +0ms

What's bizarre about this is that either Node or Engine.IO is holding the connection open after this point, but no response is being sent back to the client, causing it to hang. I think that's the bug:

1. The connection remains open; and/or
2. No response is being sent to the client.

So possibly the reason I was unable to reproduce this using JavaScript or curl was because neither was fast enough to overlap requests, which is one of Twisted's strong suits.

As an aside, does this mean that Engine.IO's server-side polling transport can only handle one POST per session at a time?

[nkzawa]

Yes, only one poll request per session is allowed.
I believe that no response is sent when data requests overlap is a bug, but will be fixed with the PR #338.

[posita]

I believe that no response is sent when data requests overlap is a bug, but will be fixed with the PR #338.

Awesome! Thanks! 👍

[nkzawa]

Fixed in 1.6.x