uv__read() blocks sometimes when reading from a pipe

[konstantin-azarov]

uv__read() immediately retries a read when a preceding read fills the entire buffer. This presents a problem when a stream being read is a pipe (for example a redirected standard input). If a process on the write end of the pipe writes exactly 64k of data to the pipe, then uv__read() will issue a second read immediately on an empty pipe, and it will block. Here is a reproduction in Node.JS:

$ node --version
v0.10.19

$ cat test.js
var s = require('sleep');
s.sleep(1)

process.stdin.on('readable', function() {
  var d = process.stdin.read(); 
  console.log('READ: ' + (d == null ? "null" : d.length));
});

setInterval(function() {
  console.log("Timeout: " + new Date());
}, 1000);

If we feed a small amount of data to the script, it works as expected, calling the interval callback every second:

$ echo "a" | node test.js
READ: 2
READ: null
Timeout: Fri Sep 27 2013 23:13:04 GMT+0000 (GMT)
Timeout: Fri Sep 27 2013 23:13:05 GMT+0000 (GMT)
Timeout: Fri Sep 27 2013 23:13:06 GMT+0000 (GMT)

If however we feed 64k of data, the callback is not called:

$ python -c 'import sys; import time; sys.stdout.write("a"*65536); time.sleep(60)' | node test.js
READ: 65536

Here is an strace output from a normal run:

$ python -c 'import sys; import time; sys.stdout.write("a"); time.sleep(60)' | strace -e trace=read,epoll_ctl,epoll_wait node test.js
<...skip...>
epoll_ctl(5, EPOLL_CTL_ADD, 0, {EPOLLIN, {u32=0, u64=0}}) = 0
epoll_wait(5, {{EPOLLIN, {u32=0, u64=0}}}, 1024, 999) = 1
read(0, "a", 65536)                     = 1
read(3, "*", 1)                         = 1
READ: 1
epoll_wait(5, {}, 1024, 992)            = 0
read(10, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"..., 4096) = 118
read(10, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"..., 4096) = 62
Timeout: Fri Sep 27 2013 23:17:03 GMT+0000 (GMT)
epoll_wait(5, {}, 1024, 1002)           = 0
Timeout: Fri Sep 27 2013 23:17:04 GMT+0000 (GMT)
epoll_wait(5, {}, 1024, 1000)           = 0
Timeout: Fri Sep 27 2013 23:17:05 GMT+0000 (GMT)

Here is an strace output from a blocked process:

$ python -c 'import sys; import time; sys.stdout.write("a"*65536); sys.stdout.flush(); time.sleep(60)' | strace -e trace=read,epoll_ctl,epoll_wait node test.js
<...skip...>
epoll_ctl(5, EPOLL_CTL_ADD, 0, {EPOLLIN, {u32=0, u64=0}}) = 0
epoll_wait(5, {{EPOLLIN, {u32=0, u64=0}}}, 1024, 1000) = 1
read(0, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 65536) = 65536
read(3, "*", 1)                         = 1
READ: 65536
read(0,

GDB stack trace:

(gdb) bt
#0  0x00007fa2e8388d2d in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000006da23d in read (__nbytes=<optimized out>, __buf=<optimized out>, __fd=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/unistd.h:45
#2  uv__read (stream=0xfb0a60) at ../deps/uv/src/unix/stream.c:960
#3  0x00000000006da901 in uv__stream_io (loop=<optimized out>, w=0xfb0ad0, events=<optimized out>) at ../deps/uv/src/unix/stream.c:1115
#4  0x00000000006df4ba in uv__io_poll (loop=0xe7eac0, timeout=956) at ../deps/uv/src/unix/linux-core.c:211
#5  0x00000000006d31f0 in uv_run (loop=0xe7eac0, mode=<optimized out>) at ../deps/uv/src/unix/core.c:317
#6  0x000000000059089d in node::Start(int, char**) ()
#7  0x00007fa2e7fdc76d in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x00000000005871a9 in _start ()

[konstantin-azarov]

It seems that an easy workaround is to stick a uv__nonblock call into uv_open_pipe. I'm not sure whether it is a proper solution or not though.

[bnoordhuis]

Thanks for the bug report, good catch. Fixed in 8fe4ca6.

[saghul]

@bnoordhuis should the fix also be applied to uv_tcp/udp_open ?

[bnoordhuis]

I'll update those as well.

[bnoordhuis]

Reopening for now. I've rolled 8fe4ca6 back in 8c9cbee. It so happens that node.js currently relies on the blocking behavior of pipes...