Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA: Input/output error

[stevenkaras]

trafficstars

I'm encountering this error after about 15 minutes of tracing a running python process.

Ubuntu 14.04, running 4.4.0-75-generic, tracing a long-lived python 2.7.6 process, built from source (e9c6b7a).

[eklitzke]

What is the address printed (i.e. the complete exception message, including the hex string at the end)? Also, can you provide me the output of pyflame -v?

[stevenkaras]

Here's the output of pyflame -v for the build that originally exited early:

Pyflame 1.5.7 (commit e9c6b7a) linux-gnu x86_64 (ABI list: 26 34)

I rebuilt it to only drop the current sample if a PTraceException is thrown, which gave me these exceptions over the last hour or so:

Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x6f6d5f5f00000051): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x6f6d5f5f00000051): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x7f5d126f5ffc): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x7f5d17fffffc): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x7f5d18e1fffc): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x7f5d18e1fffc): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x6f6d5f5f00000051): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x6f6d5f5f00000051): Input/output error
Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 45512, addr 0x50): Input/output error

[stevenkaras]

looking at /proc/45512/maps, these are some of the relevant page allocations

7f5d126f4000-7f5d128f4000 ---p 00017000 08:01 262158                     /lib/x86_64-linux-gnu/libresolv-2.19.so
7f5d14049000-7f5d18000000 ---p 00000000 00:00 0
7f5d18e1f000-7f5d1901e000 ---p 0000a000 08:01 266284                     /lib/x86_64-linux-gnu/libnss_files-2.19.so

[eklitzke]

The ones that say addr 0x50 are basically a null pointer dereference (I wrote about a related issue at https://eklitzke.org/an-unexpected-python-abi-change ), that's probably easier to debug. The other ones are hopefully fixed if we fix this case. If you want to help me debug this:

• Make sure pyflame is built with debugging symbols (I believe it is by default)
• Set a GDB breakpoint in the code path that throws the exception (i.e. at src/ptrace.cc:156)
• Get the Pyflame backtrace (using bt in GDB) when you hit the breakpoint

That will help figure out where in the code the error is happening.

Also -- are you profiling a regular Python 2.7 process, or some kind of embedded Python build (e.g. a uwsgi worker process)?

[stevenkaras]

This is a regular Python 2.7.6 process. Here's the backtrace:

#0  pyflame::PtracePeek (pid=pid@entry=45512, addr=addr@entry=80) at ptrace.cc:156
#1  0x000000000040d402 in pyflame::py26::FollowFrame (pid=pid@entry=45512, frame=140024926446528, stack=stack@entry=0x7fffffffe1d0) at ./frob.cc:229
#2  0x000000000040d4f3 in pyflame::py26::FollowFrame (pid=pid@entry=45512, frame=140037744176656, stack=stack@entry=0x7fffffffe1d0) at ./frob.cc:239
#3  0x000000000040d8a0 in pyflame::py26::GetThreads (pid=45512, addrs=..., enable_threads=false) at ./frob.cc:288
#4  0x000000000040ae10 in pyflame::PyFrob::GetThreads (this=this@entry=0x7fffffffe450) at pyfrob.cc:199
#5  0x0000000000405fa1 in pyflame::Prober::ProbeLoop (this=this@entry=0x7fffffffe410, frobber=...) at prober.cc:364
#6  0x0000000000403331 in main (argc=<optimized out>, argv=0x7fffffffe588) at pyflame.cc:37

[bk-equityzen]

I've also gotten this issue profiling a django uwsgi app: Unexpected ptrace(2) exception: Failed to PTRACE_PEEKDATA (pid 30398, addr 0x2f0000008e): Input/output error

Sometimes happens after a few seconds of clicking around, sometimes doesn't happen for a while, my current workaround is to profile in smaller bursts

[eklitzke]

@stevenkaras That is interesting because that shows pointers well beyond where I would expect the stack to end. This differs from system to system, but here's what I see locally:

$ cat /proc/4006/maps
55c16bb0e000-55c16bb10000 r-xp 00000000 fd:01 139319                     /usr/bin/python3.6
55c16bd0f000-55c16bd10000 r--p 00001000 fd:01 139319                     /usr/bin/python3.6
55c16bd10000-55c16bd11000 rw-p 00002000 fd:01 139319                     /usr/bin/python3.6
55c16c16a000-55c16c2da000 rw-p 00000000 00:00 0                          [heap]
7fdbc5f02000-7fdbc5f42000 rw-p 00000000 00:00 0 
7fdbc5f42000-7fdbc5f46000 r-xp 00000000 fd:01 666378                     /usr/lib64/python3.6/lib-dynload/_random.cpython-36m-x86_64-linux-gnu.so
7fdbc5f46000-7fdbc6145000 ---p 00004000 fd:01 666378                     /usr/lib64/python3.6/lib-dynload/_random.cpython-36m-x86_64-linux-gnu.so
7fdbc6145000-7fdbc6146000 r--p 00003000 fd:01 666378                     /usr/lib64/python3.6/lib-dynload/_random.cpython-36m-x86_64-linux-gnu.so
7fdbc6146000-7fdbc6147000 rw-p 00004000 fd:01 666378                     /usr/lib64/python3.6/lib-dynload/_random.cpython-36m-x86_64-linux-gnu.so
7fdbc6147000-7fdbc6149000 r-xp 00000000 fd:01 663389                     /usr/lib64/python3.6/lib-dynload/_bisect.cpython-36m-x86_64-linux-gnu.so
7fdbc6149000-7fdbc6348000 ---p 00002000 fd:01 663389                     /usr/lib64/python3.6/lib-dynload/_bisect.cpython-36m-x86_64-linux-gnu.so
7fdbc6348000-7fdbc6349000 r--p 00001000 fd:01 663389                     /usr/lib64/python3.6/lib-dynload/_bisect.cpython-36m-x86_64-linux-gnu.so
7fdbc6349000-7fdbc634a000 rw-p 00002000 fd:01 663389                     /usr/lib64/python3.6/lib-dynload/_bisect.cpython-36m-x86_64-linux-gnu.so
7fdbc634a000-7fdbc6360000 r-xp 00000000 fd:01 666381                     /usr/lib64/python3.6/lib-dynload/_sha3.cpython-36m-x86_64-linux-gnu.so
7fdbc6360000-7fdbc655f000 ---p 00016000 fd:01 666381                     /usr/lib64/python3.6/lib-dynload/_sha3.cpython-36m-x86_64-linux-gnu.so
7fdbc655f000-7fdbc6560000 r--p 00015000 fd:01 666381                     /usr/lib64/python3.6/lib-dynload/_sha3.cpython-36m-x86_64-linux-gnu.so
7fdbc6560000-7fdbc6562000 rw-p 00016000 fd:01 666381                     /usr/lib64/python3.6/lib-dynload/_sha3.cpython-36m-x86_64-linux-gnu.so
7fdbc6562000-7fdbc656f000 r-xp 00000000 fd:01 666144                     /usr/lib64/python3.6/lib-dynload/_blake2.cpython-36m-x86_64-linux-gnu.so
7fdbc656f000-7fdbc676e000 ---p 0000d000 fd:01 666144                     /usr/lib64/python3.6/lib-dynload/_blake2.cpython-36m-x86_64-linux-gnu.so
7fdbc676e000-7fdbc676f000 r--p 0000c000 fd:01 666144                     /usr/lib64/python3.6/lib-dynload/_blake2.cpython-36m-x86_64-linux-gnu.so
7fdbc676f000-7fdbc6770000 rw-p 0000d000 fd:01 666144                     /usr/lib64/python3.6/lib-dynload/_blake2.cpython-36m-x86_64-linux-gnu.so
7fdbc6770000-7fdbc6786000 r-xp 00000000 fd:01 135588                     /usr/lib64/libz.so.1.2.11
7fdbc6786000-7fdbc6985000 ---p 00016000 fd:01 135588                     /usr/lib64/libz.so.1.2.11
7fdbc6985000-7fdbc6986000 r--p 00015000 fd:01 135588                     /usr/lib64/libz.so.1.2.11
7fdbc6986000-7fdbc6987000 rw-p 00000000 00:00 0 
7fdbc6987000-7fdbc6be3000 r-xp 00000000 fd:01 139043                     /usr/lib64/libcrypto.so.1.1.0g
7fdbc6be3000-7fdbc6de3000 ---p 0025c000 fd:01 139043                     /usr/lib64/libcrypto.so.1.1.0g
7fdbc6de3000-7fdbc6e00000 r--p 0025c000 fd:01 139043                     /usr/lib64/libcrypto.so.1.1.0g
7fdbc6e00000-7fdbc6e0c000 rw-p 00279000 fd:01 139043                     /usr/lib64/libcrypto.so.1.1.0g
7fdbc6e0c000-7fdbc6e0f000 rw-p 00000000 00:00 0 
7fdbc6e0f000-7fdbc6e71000 r-xp 00000000 fd:01 139045                     /usr/lib64/libssl.so.1.1.0g
7fdbc6e71000-7fdbc7071000 ---p 00062000 fd:01 139045                     /usr/lib64/libssl.so.1.1.0g
7fdbc7071000-7fdbc7075000 r--p 00062000 fd:01 139045                     /usr/lib64/libssl.so.1.1.0g
7fdbc7075000-7fdbc707b000 rw-p 00066000 fd:01 139045                     /usr/lib64/libssl.so.1.1.0g
7fdbc707b000-7fdbc7081000 r-xp 00000000 fd:01 666367                     /usr/lib64/python3.6/lib-dynload/_hashlib.cpython-36m-x86_64-linux-gnu.so
7fdbc7081000-7fdbc7280000 ---p 00006000 fd:01 666367                     /usr/lib64/python3.6/lib-dynload/_hashlib.cpython-36m-x86_64-linux-gnu.so
7fdbc7280000-7fdbc7281000 r--p 00005000 fd:01 666367                     /usr/lib64/python3.6/lib-dynload/_hashlib.cpython-36m-x86_64-linux-gnu.so
7fdbc7281000-7fdbc7282000 rw-p 00006000 fd:01 666367                     /usr/lib64/python3.6/lib-dynload/_hashlib.cpython-36m-x86_64-linux-gnu.so
7fdbc7282000-7fdbc728c000 r-xp 00000000 fd:01 666397                     /usr/lib64/python3.6/lib-dynload/math.cpython-36m-x86_64-linux-gnu.so
7fdbc728c000-7fdbc748b000 ---p 0000a000 fd:01 666397                     /usr/lib64/python3.6/lib-dynload/math.cpython-36m-x86_64-linux-gnu.so
7fdbc748b000-7fdbc748c000 r--p 00009000 fd:01 666397                     /usr/lib64/python3.6/lib-dynload/math.cpython-36m-x86_64-linux-gnu.so
7fdbc748c000-7fdbc748e000 rw-p 0000a000 fd:01 666397                     /usr/lib64/python3.6/lib-dynload/math.cpython-36m-x86_64-linux-gnu.so
7fdbc748e000-7fdbc750e000 rw-p 00000000 00:00 0 
7fdbc750e000-7fdbc7518000 r-xp 00000000 fd:01 666389                     /usr/lib64/python3.6/lib-dynload/_struct.cpython-36m-x86_64-linux-gnu.so
7fdbc7518000-7fdbc7718000 ---p 0000a000 fd:01 666389                     /usr/lib64/python3.6/lib-dynload/_struct.cpython-36m-x86_64-linux-gnu.so
7fdbc7718000-7fdbc7719000 r--p 0000a000 fd:01 666389                     /usr/lib64/python3.6/lib-dynload/_struct.cpython-36m-x86_64-linux-gnu.so
7fdbc7719000-7fdbc771b000 rw-p 0000b000 fd:01 666389                     /usr/lib64/python3.6/lib-dynload/_struct.cpython-36m-x86_64-linux-gnu.so
7fdbc771b000-7fdbc7824000 rw-p 00000000 00:00 0 
7fdbc7824000-7fdbc7827000 r-xp 00000000 fd:01 666368                     /usr/lib64/python3.6/lib-dynload/_heapq.cpython-36m-x86_64-linux-gnu.so
7fdbc7827000-7fdbc7a26000 ---p 00003000 fd:01 666368                     /usr/lib64/python3.6/lib-dynload/_heapq.cpython-36m-x86_64-linux-gnu.so
7fdbc7a26000-7fdbc7a27000 r--p 00002000 fd:01 666368                     /usr/lib64/python3.6/lib-dynload/_heapq.cpython-36m-x86_64-linux-gnu.so
7fdbc7a27000-7fdbc7a29000 rw-p 00003000 fd:01 666368                     /usr/lib64/python3.6/lib-dynload/_heapq.cpython-36m-x86_64-linux-gnu.so
7fdbc7a29000-7fdbc7aa9000 rw-p 00000000 00:00 0 
7fdbc7aa9000-7fdbce678000 r--p 00000000 fd:01 543636                     /usr/lib/locale/locale-archive
7fdbce678000-7fdbce824000 r-xp 00000000 fd:01 140221                     /usr/lib64/libc-2.26.so
7fdbce824000-7fdbcea24000 ---p 001ac000 fd:01 140221                     /usr/lib64/libc-2.26.so
7fdbcea24000-7fdbcea28000 r--p 001ac000 fd:01 140221                     /usr/lib64/libc-2.26.so
7fdbcea28000-7fdbcea2a000 rw-p 001b0000 fd:01 140221                     /usr/lib64/libc-2.26.so
7fdbcea2a000-7fdbcea2e000 rw-p 00000000 00:00 0 
7fdbcea2e000-7fdbceb78000 r-xp 00000000 fd:01 177305                     /usr/lib64/libm-2.26.so
7fdbceb78000-7fdbced77000 ---p 0014a000 fd:01 177305                     /usr/lib64/libm-2.26.so
7fdbced77000-7fdbced78000 r--p 00149000 fd:01 177305                     /usr/lib64/libm-2.26.so
7fdbced78000-7fdbced79000 rw-p 0014a000 fd:01 177305                     /usr/lib64/libm-2.26.so
7fdbced79000-7fdbced7b000 r-xp 00000000 fd:01 168001                     /usr/lib64/libutil-2.26.so
7fdbced7b000-7fdbcef7a000 ---p 00002000 fd:01 168001                     /usr/lib64/libutil-2.26.so
7fdbcef7a000-7fdbcef7b000 r--p 00001000 fd:01 168001                     /usr/lib64/libutil-2.26.so
7fdbcef7b000-7fdbcef7c000 rw-p 00002000 fd:01 168001                     /usr/lib64/libutil-2.26.so
7fdbcef7c000-7fdbcef7f000 r-xp 00000000 fd:01 155161                     /usr/lib64/libdl-2.26.so
7fdbcef7f000-7fdbcf17e000 ---p 00003000 fd:01 155161                     /usr/lib64/libdl-2.26.so
7fdbcf17e000-7fdbcf17f000 r--p 00002000 fd:01 155161                     /usr/lib64/libdl-2.26.so
7fdbcf17f000-7fdbcf180000 rw-p 00003000 fd:01 155161                     /usr/lib64/libdl-2.26.so
7fdbcf180000-7fdbcf199000 r-xp 00000000 fd:01 177313                     /usr/lib64/libpthread-2.26.so
7fdbcf199000-7fdbcf398000 ---p 00019000 fd:01 177313                     /usr/lib64/libpthread-2.26.so
7fdbcf398000-7fdbcf399000 r--p 00018000 fd:01 177313                     /usr/lib64/libpthread-2.26.so
7fdbcf399000-7fdbcf39a000 rw-p 00019000 fd:01 177313                     /usr/lib64/libpthread-2.26.so
7fdbcf39a000-7fdbcf39e000 rw-p 00000000 00:00 0 
7fdbcf39e000-7fdbcf664000 r-xp 00000000 fd:01 135367                     /usr/lib64/libpython3.6m.so.1.0
7fdbcf664000-7fdbcf863000 ---p 002c6000 fd:01 135367                     /usr/lib64/libpython3.6m.so.1.0
7fdbcf863000-7fdbcf869000 r--p 002c5000 fd:01 135367                     /usr/lib64/libpython3.6m.so.1.0
7fdbcf869000-7fdbcf8cc000 rw-p 002cb000 fd:01 135367                     /usr/lib64/libpython3.6m.so.1.0
7fdbcf8cc000-7fdbcf8fd000 rw-p 00000000 00:00 0 
7fdbcf8fd000-7fdbcf922000 r-xp 00000000 fd:01 135132                     /usr/lib64/ld-2.26.so
7fdbcf951000-7fdbcf991000 rw-p 00000000 00:00 0 
7fdbcf9b6000-7fdbcfafa000 rw-p 00000000 00:00 0 
7fdbcfb1a000-7fdbcfb21000 r--s 00000000 fd:01 135435                     /usr/lib64/gconv/gconv-modules.cache
7fdbcfb21000-7fdbcfb22000 r--p 00024000 fd:01 135132                     /usr/lib64/ld-2.26.so
7fdbcfb22000-7fdbcfb23000 rw-p 00025000 fd:01 135132                     /usr/lib64/ld-2.26.so
7fdbcfb23000-7fdbcfb24000 rw-p 00000000 00:00 0 
7ffd515b8000-7ffd515d9000 rw-p 00000000 00:00 0                          [stack]
7ffd515da000-7ffd515dd000 r--p 00000000 00:00 0                          [vvar]
7ffd515dd000-7ffd515df000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]

So on my system in this particular run the stack was in the range 7ffd515b8000-7ffd515d9000 which is typical (the exact numbers can vary). Normally it is some number like 0x7ff and then other digits after that, but before 0x7ffff...

You're seeing a stack entry well beyond that, i.e. from your trace:

#2  0x000000000040d4f3 in pyflame::py26::FollowFrame (pid=pid@entry=45512, frame=140037744176656, stack=stack@entry=0x7fffffffe1d0) at ./frob.cc:239

That address is 7728 bytes before where I expect userspace memory to end (0x7fffffffffff). Would need more data from gdb to debug further.

@bk-equityzen I would be interested to see what the memory map looks like in that situation as it appears not to be at the top of user memory. You can use /proc/PID/maps from the process as I did here to look at that.

[rousseldenis]

I rebuilt it to only drop the current sample if a PTraceException is thrown, which gave me these exceptions over the last hour or so:

I have the same errors on Ubuntu 18.10