http: master tries write twice on EPIPE #7155

Closed
bnoordhuis opened this Issue Feb 20, 2014 · 6 comments

Projects

None yet

4 participants

@bnoordhuis
Member

Contrived test case for brevity's sake.

var http = require('http');

http.createServer(function(req, res) {
  req.on('data', function(buf) {
    res.write('pong');
    res.end();
  });
  this.close();
}).listen(function() {
  var req = http.request({
    agent: false,
    host: this.address().address,
    port: this.address().port,
    method: 'POST',
  });

  req.on('response', function(res) {
    res.on('data', function(buf) {
      req.write('ping');
      req.end();
    });
  });

  req.write('ping');
});
$ master/out/Release/node t.js

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: write EPIPE
    at errnoException (net.js:904:11)
    at Object.afterWrite (net.js:720:19)

That's the expected behavior but when you strace it:

write(11, "0\r\n\r\n", 5)               = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=23294, si_uid=1000} ---
write(11, "0\r\n\r\n", 5)               = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=23294, si_uid=1000} ---
@indutny
Member
indutny commented Feb 27, 2014

Can't reproduce it on mac with both v0.10 and v0.11, is this issue still happening for you? Is it linux specific?

@bnoordhuis
Member

I can reproduce it on OS X with commit 269de79 (current HEAD of master, @saghul's first node patch?)

$ uname -a
Darwin hermes.local 12.5.0 Darwin Kernel Version 12.5.0: Sun Sep 29 13:33:47 PDT 2013; root:xnu-2050.48.12~1/RELEASE_X86_64 x86_64

$ sudo dtruss -t write master/out/Release/node issue7155.js
events.js:82
      throw er; // Unhandled 'error' event
            ^
Error: write EPIPE
    at exports._errnoException (util.js:745:11)
    at Object.afterWrite (net.js:772:14)
SYSCALL(args)            = return
write(0x4, "*\0", 0x1)           = 1 0
write(0xC, "POST / HTTP/1.1\r\nHost: 0.0.0.0:62894\r\nConnection: close\r\nTransfer-Encoding: chunked\r\n\r\n4\r\nping\r\n\0", 0x60)             = 96 0
write(0xD, "HTTP/1.1 200 OK\r\nDate: Thu, 27 Feb 2014 20:41:05 GMT\r\nConnection: close\r\nTransfer-Encoding: chunked\r\n\r\n4\r\npong\r\n\0", 0x70)             = 112 0
write(0xD, "0\r\n\r\n\0", 0x5)           = 5 0
write(0xC, "4\r\nping\r\n\0", 0x9)               = 9 0
write(0xC, "\0", 0x5)            = -1 Err#32
write(0xC, "\0", 0x5)            = -1 Err#32
write(0x4, "*\0", 0x1)           = 1 0

(Err#32 is EPIPE.)

@saghul
Member
saghul commented Feb 27, 2014

On 02/27/2014 09:47 PM, Ben Noordhuis wrote:

I can reproduce it on OS X with commit 269de79
269de79 (current HEAD of master,
@saghul https://github.com/saghul's first node patch?)

Sssh, don't tell anyone :-P

@tjfontaine

Isn't this the expected behavior from uv_try_write?

see the following:

dtrace -c './node t.js' -n 'pid$target::uv_write:entry { trace(arg2); } pid$target::uv_try_write:entry { trace(arg1); } uv*:::tick-start {}'
dtrace: description 'pid$target::uv_write:entry ' matched 3 probes
events.js:82
      throw er; // Unhandled 'error' event
            ^
Error: write EPIPE
    at exports._errnoException (util.js:745:11)
    at Object.afterWrite (net.js:772:14)
dtrace: pid 10623 has exited
CPU     ID                    FUNCTION:NAME
  0  75237                uv_run:tick-start 
  0  75550               uv_try_write:entry         134493656
  0  75237                uv_run:tick-start 
  0  75550               uv_try_write:entry         134491272
  0  75550               uv_try_write:entry         134491288
  0  75237                uv_run:tick-start 
  0  75550               uv_try_write:entry         134491256
  0  75550               uv_try_write:entry         134491272
  0  74989                   uv_write:entry         134491272
  0  75237                uv_run:tick-start
@bnoordhuis
Member

I don't know about 'expected' but yes, it seems src/stream_wrap.cc posts a new WriteWrap when uv_try_write() fails. Not the worst thing in the world but kind of wasteful in this case.

@indutny indutny added a commit to indutny/node that referenced this issue Feb 28, 2014
@indutny indutny stream_wrap: don't write twice on uv_try_write err
fix #7155
2835689
@indutny
Member
indutny commented Feb 28, 2014

Should be fixed by #7207 , thanks for reporting Ben.

@indutny indutny closed this in 3b88dc6 Feb 28, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment