EPIPE with unix sockets from v4.1.2

[gramakri]

I get intermittent EPIPE with the following code starting from v4.1.2. This code works consistently fine with <= 4.1.1.

var http = require('http');

var data = JSON.stringify({ Cmd: [ 'env' ], AttachStdout: true, AttachStderr: true });

var req = http.request({
    path: '/v1.19/containers/mysql/exec',
    method: 'POST',
    headers: { 'Content-Type': 'application/json', 'Content-Length': data.length },
    key: undefined,
    cert: undefined,
    ca: undefined,
    socketPath: '/var/run/docker.sock' }, function () { });

req.on('response', function (res) {
    var chunks = '';
    res.on('data', function(chunk) {
        chunks += chunk;
    });

    res.on('end', function() {
        console.log('Received: %s', chunks);
    });
});

req.on('error', function(error) { console.log(error); });

req.write(data);
req.end();

Test output (this is a continuous shell session):

# /usr/local/node-4.1.0/bin/node test.js 
Received: {"Id":"879a1923b1b9c0645e062f4b66b34d89678eaee098007989faf0b3bdd25be88c"}

#/usr/local/node-4.1.1/bin/node test.js
Received: {"Id":"220d1a2fdf0ed970e49f0df8a81763ec83783c88cab3a8dbd0dbe83152a02ec3"}

#/usr/local/node-4.1.2/bin/node test.js
{ [Error: write EPIPE]
  code: 'EPIPE',
  errno: 'EPIPE',
  syscall: 'write',
  address: undefined }

#/usr/local/node-4.2.1/bin/node test.js
Received: {"Id":"8ae4fd9dea746c52f9d7d6675a2556b13e48c49ee714b3ba2950974a5c619e70"}

#/usr/local/node-4.2.1/bin/node test.js
{ [Error: write EPIPE]
  code: 'EPIPE',
  errno: 'EPIPE',
  syscall: 'write',
  address: undefined }

#/usr/local/node-4.2.2/bin/node test.js
{ [Error: write EPIPE]
  code: 'EPIPE',
  errno: 'EPIPE',
  syscall: 'write',
  address: undefined }

#/usr/local/node-5.0.0/bin/node test.js
{ [Error: write EPIPE]
  code: 'EPIPE',
  errno: 'EPIPE',
  syscall: 'write',
  address: undefined }

#/usr/local/node-4.1.0/bin/node test.js
Received: {"Id":"49d97ac0920cad11956ac795032df2ec6d38b13f144f0f3c0875f574926b4e7e"}

#/usr/local/node-4.1.0/bin/node test.js
Received: {"Id":"9c2035823fd5d0cfc8dd12a8466b8a7643c3e6721729002905f4b1bd33a56156"}

Note how the request works intermittently for >= 4.1.2. If I run it 10 times, it will fail 8 times. But it consistently works below 4.1.1.

The above example was derived from https://github.com/apocas/docker-modem/blob/master/lib/modem.js#L156 (@apocas). I hit this error consistently with dockerode.

[bnoordhuis]

Can you try bisecting the commits between v4.1.1 and v4.1.2? I went over them and I didn't really see anything that stands out except maybe fb7a491. It's probably not the libuv upgrade in 4c59407 or the V8 upgrade in 5a9e795.

[gramakri]

@bnoordhuis ok, i can try that tonight

[Fishrock123]

fb7a491 Doesn't touch net so I think it's most likely the libuv upgrade.

[gramakri]

Just leaving a note that I am yet to get to this.

[gramakri]

I can reproduce this with docker 1.9 as well (previously it was with 1.7)

[gramakri]

@bnoordhuis @indutny @Fishrock123

Just bisected. 99943e1 is the commit. Reverting that fixes the problem. This is easy to reproduce if you have docker.

1. docker run -d --name mysql ubuntu sleep 10000
2. run the above code. you will get EPIPE
3. When 99943e1 is reverted, it will print the exec container id.

[indutny]

@gramakri may I ask you to collect strace node test.js output during failure?

[gramakri]

@indutny Here you go

trace.txt

[gramakri]

For good measure, here's the strace when the commit is reverted. Let me know if you need anything else.

trace2.txt

[indutny]

Oh, I think I know what's happening:

write(10, "POST /v1.19/containers/mysql/exe"..., 189) = 189
write(10, "", 0)                        = -1 EPIPE (Broken pipe)

Looks like mysql container is closing it's read side right after reading the request from it. I would say that node should not do any empty write, but after all it seems to be a mistake on other side of the pipe (i.e. mysql or whatever provides this docker pipe).

Still let's keep this issue open until I will figure out how to remove that empty write.

[gramakri]

@indutny this is basically a HTTP request over unix sockets (docker provides a REST api over /var/run/docker.sock). Sorry for the misleading with 'mysql', you can ignore that since the test case has nothing to do with mysql (it can be named foobar). There are no containers involved in this test case either other than the fact this REST call creates a container. In short, if I understand you correctly, the docker server/daemon is closing the write part of the connection after reading it's stuff. I thought this was valid behavior to close down one end of the socket (shutdown) but I am no expert :-)

[indutny]

@gramakri while it is a valid UNIX socket usage, I do not think that it could be valid for HTTP.

[indutny]

I was thinking more about it and it should be perfectly fine to send a follow up empty TCP packets in case of any kind of HTTP request. I'm going to close it, and open an issue for empty TCP packet, but it is going to be a feature request, not a bug report.

Sorry!