Processes with stdout=PTY hang on select() because of glibc buffering

[sroettger]

When calling readline or readuntil on a process tube, the tube sometimes gets blocked on select if more than 4096 bytes were received.
It's easier to explain with an example:

r = process('./test', stdout=PIPE)
r.readuntil('A')
r.readuntil('B')
print('works with PIPE')

r = process('./test') # default: stdout=PTY
r.readuntil('A')
r.readuntil('B')
print('works without PIPE')

where ./test is just a small binary that prints 4096 A's and 1 B

#include <stdio.h>
#include <string.h>

#define OFF 4096

int main(int argc, char *argv[])
{
  setbuf(stdout, 0);
  char buf[10000] = {0};
  memset(buf, 'A', OFF);
  buf[OFF] = 'B';
  puts(buf);
  getchar();
  return 0;
}

The expected outcome is that the script finishes, though it blocks on the second r.readuntil('B').
When stracing the script, you can see that it receives the complete data but then blocks on a select call:

read(9, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"..., 4096) = 4095
read(9, "AB\n", 4096)                   = 3
select(10, [9], [], [], {1048575, 999794}

[zachriggle]

I can confirm I can repro this.

The issue is Python not doing what it's supposed to (a single read call shouldn't equal two syscalls) and then we block* on select to poll for more data -- but there is none, because Python already received it.

(*"block" until the default timeout expires)

[zachriggle]

$ strace -q -yy -P /dev/ptmx python test.py
...
select(10, [9</dev/ptmx>], [], [], {1048575, 999994}) = 1 (in [9], left {1048575, 999988})
Calling self.proc.stdout.read(4096)
fstat(9</dev/ptmx>, {st_mode=S_IFCHR|0666, st_rdev=makedev(5, 2), ...}) = 0
ioctl(9</dev/ptmx>, TCGETS, {B38400 -opost -isig -icanon -echo ...}) = 0
read(9</dev/ptmx>, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"..., 4096) = 4095
read(9</dev/ptmx>, "AB\n", 4096)        = 3
Returned 4096 bytes from .read
select(10, [9</dev/ptmx>], [], [], {1048575, 999876}

[zachriggle]

It looks like Python internally does file_read -> Py_UniversalNewlineFread -> fread which does some internal buffering even though it shouldn't.

SYS_write(1, "Calling self.proc.stdout.read(40"..., 35Calling self.proc.stdout.read(4096))                                                                       = 35
SYS_write(1, "\033[K\n", 4
)                                                                                                   = 4
python->fread(0x117b9b4, 1, 4096, 0x1178b50 <unfinished ...>
SYS_fstat(9, 0x7ffeaeae1dc0)                                                                                                  = 0
SYS_ioctl(9, 0x5401, 0x7ffeaeae1d30, 0x7f94262be700)                                                                          = 0
SYS_read(9, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"..., 4096)                                                                      = 4095
SYS_read(9, "AB\n", 4096)                                                                                                     = 3
<... fread resumed> )                                                                                                         = 4096
SYS_write(1, "Returned 4096 bytes from .read", 30Returned 4096 bytes from .read)                                                                            = 30
SYS_write(1, "\033[K\n", 4

[zachriggle]

This works around the issue, but I don't like it. I'm still not sure why fread is calling read twice.

diff --git a/pwnlib/tubes/process.py b/pwnlib/tubes/process.py
index 8028457..6667214 100644
--- a/pwnlib/tubes/process.py
+++ b/pwnlib/tubes/process.py
@@ -676,6 +676,15 @@ class process(tube):
         if not self.connected_raw('recv'):
             raise EOFError
 
+        # Work-around https://github.com/Gallopsled/pwntools/issues/1038
+        try:
+            with self.local(timeout=0):
+                data = self.proc.stdout.read()
+                if data:
+                    return data
+        except IOError as (err, strerror):
+            pass
+
         if not self.can_recv_raw(self.timeout):
             return ''

[zachriggle]

This can be reproduced with minimal pwntools involvement. The second call to select should succeed, but hangs. Interestingly, it doesn't always hang under strace.

from pwn import *
import select

r = process('./test')
timeout = 60
stdout = r.stdout

select.select([stdout], [], [], timeout) == ([stdout], [], [])
data = stdout.read(4096)
print "Got", len(data)
select.select([stdout], [], [], timeout) == ([stdout], [], [])

[zachriggle]

Switching between PIPE and PTY yields some interesting results. These are in line with the purpose of the report.

[┤] Starting local process './test'
[+] Starting local process './test': pid 102619
select(6, [5<pipe:[471529]>], [], [], {60, 0}) = 1 (in [5], left {59, 999998})
read(5<pipe:[471529]>, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"..., 4096) = 4096
Got 4096
select(6, [5<pipe:[471529]>], [], [], {60, 0}) = 1 (in [5], left {59, 999998})
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=102619, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
[*] Stopped process './test' (pid 102619)
+++ exited with 0 +++

[┤] Starting local process './test'
[+] Starting local process './test': pid 102397
select(6, [5</dev/ptmx>], [], [], {60, 0}) = 1 (in [5], left {59, 999996})
read(5</dev/ptmx>, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"..., 4096) = 4095
read(5</dev/ptmx>, "AB\n", 4096)        = 3
Got 4096
select(6, [5</dev/ptmx>], [], [], {60, 0}

[zachriggle]

So apparently what's happening is:

• The first call to read(2) inside of fread returns 0xfff
• fread still wants one more byte, and calls __underflow
• __underflow jumps into _IO_file_underflow
• _IO_file_underflow ends up calling _IO_OVERFLOW which is _IO_file_overflow

Aaaaand I'm too tired to continue troubleshooting.

[zachriggle]

First read:

*RCX  0x1000
 RDX  0x1000
*RDI  0x5
 RSI  0x834884 ◂— 0x6e6f687479702f62 ('b/python')

 ► f 0     7ffff71d7220 read
   f 1     7ffff7158f79 __GI__IO_file_xsgetn+185
   f 2     7ffff714e236 fread+150
   f 3           437fbe Py_UniversalNewlineFread.part.9+62
   f 4           437fbe Py_UniversalNewlineFread.part.9+62
   f 5           4388f6 file_read+278
   f 6           4388f6 file_read+278
   f 7           4b7932 PyEval_EvalFrameEx+29090
   f 8           4b7932 PyEval_EvalFrameEx+29090
   f 9           4b9aec PyEval_EvalCodeEx+2044
   f 10           4b9bf9 PyEval_EvalCode+25

Second read

*RCX  0x8bc690 —▸ 0x7ffff74a5198 (main_arena+1656) —▸ 0x835880 —▸ 0x414141 (chmod@plt+1) ◂— ...
*RDX  0x1000
*RDI  0x5
 RSI  0x8bc690 —▸ 0x7ffff74a5198 (main_arena+1656) —▸ 0x835880 —▸ 0x414141 (chmod@plt+1) ◂— ...

 ► f 0     7ffff71d7220 read
   f 1     7ffff715a5e8 _IO_file_underflow+328
   f 2     7ffff7159058 __GI__IO_file_xsgetn+408
   f 3     7ffff714e236 fread+150
   f 4           437fbe Py_UniversalNewlineFread.part.9+62
   f 5           437fbe Py_UniversalNewlineFread.part.9+62
   f 6           4388f6 file_read+278
   f 7           4388f6 file_read+278
   f 8           4b7932 PyEval_EvalFrameEx+29090
   f 9           4b7932 PyEval_EvalFrameEx+29090
   f 10           4b9aec PyEval_EvalCodeEx+2044

[zachriggle]

This patch also resolves the issue sufficiently, by avoiding fread via file_read.

diff --git a/pwnlib/tubes/process.py b/pwnlib/tubes/process.py
index 8028457..0182b0c 100644
--- a/pwnlib/tubes/process.py
+++ b/pwnlib/tubes/process.py
@@ -685,7 +685,7 @@ class process(tube):
         data = ''
 
         try:
-            data = self.proc.stdout.read(numb)
+            data = os.read(self.proc.stdout.fileno(), numb)
         except IOError as (err, strerror):
             pass

@idolf what do you think?

[zachriggle]

After a bit more digging, this is entirely the fault of Python's file implementation and our use of os.fdopen() in the case of using PTYs.

pwnlib/tubes/process.py-333-        if self.pty is not None:
pwnlib/tubes/process.py-334-            if stdin is slave:
pwnlib/tubes/process.py:335:                self.proc.stdin = os.fdopen(os.dup(master), 'r+')
pwnlib/tubes/process.py-336-            if stdout is slave:
pwnlib/tubes/process.py:337:                self.proc.stdout = os.fdopen(os.dup(master), 'r+')
pwnlib/tubes/process.py-338-            if stderr is slave:
pwnlib/tubes/process.py:339:                self.proc.stderr = os.fdopen(os.dup(master), 'r+')

Unrelated, the r+ is a bit misleading, we should probably document why somebody might want to read from STDIN (tl;dr is fd on pwnable.kr).

[zachriggle]

Real fix is here, PR coming soon:

diff --git a/pwnlib/tubes/process.py b/pwnlib/tubes/process.py
index 8028457..2f54ed1 100644
--- a/pwnlib/tubes/process.py
+++ b/pwnlib/tubes/process.py
@@ -332,11 +332,11 @@ class process(tube):
 
         if self.pty is not None:
             if stdin is slave:
-                self.proc.stdin = os.fdopen(os.dup(master), 'r+')
+                self.proc.stdin = os.fdopen(os.dup(master), 'r+', 0)
             if stdout is slave:
-                self.proc.stdout = os.fdopen(os.dup(master), 'r+')
+                self.proc.stdout = os.fdopen(os.dup(master), 'r+', 0)
             if stderr is slave:
-                self.proc.stderr = os.fdopen(os.dup(master), 'r+')
+                self.proc.stderr = os.fdopen(os.dup(master), 'r+', 0)
 
             os.close(master)
             os.close(slave)

[zachriggle]

@idolf Need to cut a 3.9.1 release for this. I've already updated the changelog and handled all of the merging (stable -> beta-staging -> dev). Just need to wait for CI checks to pass.

[TethysSvensson]

This was fixed in #1040 and the fix was released in 3.9.1.