Can't trace a program running inside docker container by pid or ppid

[Abeautifulsnow]

Description

Hi, before going further, allow me to clarify that maybe this issue seems to be somewhat similar to(not very sure) - Tracing a program running inside docker container may fail #159. Ahh, I've read all the conversations between yours. You've solved the issue metioned by that author. But my situation is a little different from him.

I also have an application running inside the docker container and want to profile it by pid. Through the htop and ps -ef command, I record the pid and parent pid. When I use <austin -Cp> or <austin -p> [pip] to display the stack of the frames it fails.

              _   _
 __ _ _  _ __| |_(_)_ _
/ _` | || (_-<  _| | ' \
\__,_|\_,_/__/\__|_|_||_| 3.6.0 [gcc 9.4.0]

Parent process
👽 Not a Python process.

🚼 It looks like you are trying to profile a process that is not a Python
process, and that has not spawned any child Python processes. Make sure that
you are targeting the right application.

Versions

austin: 3.6.0
os:

NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"

Additional Information

Based on this minor issue, I switched over to py-spy. py-spy is worked for me. It can retrieve the information by the pid and parent pid. - For example, py-spy top -p 22227 will show:

Collecting samples from '/usr/local/bin/python /usr/local/bin/uvicorn energy_api.main:app --host 0.0.0.0 --port 9000' (python v3.8.18)
Total Samples 1623
GIL: 100.00%, Active: 100.00%, Threads: 1

  %Own   %Total  OwnTime  TotalTime  Function (filename)
 39.13%  47.83%    4.16s     4.68s   pslq (mpmath/identification.py)
  0.00%   0.00%    2.86s     2.86s   get_values (pandas/core/internals/blocks.py)
...

I can't put my finger on what the underlying cause is. If I missed something, please let me know. THX.

[P403n1x87]

@Abeautifulsnow thanks for reporting this. Would you be able to see if Austin 3.5 works by any chance? This might be a regression introduced in 3.6, albeit there doesn't seem to be an indication of this in CI. Many thanks!

[Abeautifulsnow]

Would you be able to see if Austin 3.5 works by any chance? This might be a regression introduced in 3.6, albeit there doesn't seem to be an indication of this in CI. Many thanks!

@P403n1x87 No, it still doesn't seem to work after installing version 3.5 as you suggested. The only output was the logo text, then it produced nothing more after. I wait for about 2 minutes and It seems to be stuck in some kind of infinite loop or any other problem.

$ austin -p 22225
              _   _
 __ _ _  _ __| |_(_)_ _
/ _` | || (_-<  _| | ' \
\__,_|\_,_/__/\__|_|_||_| 3.5.0 [GCC 9.4.0]
^C

Oh, right, I discover that austinp command can print out some information from inside that docker container.

$ austinp -p 22225
# map: 55d13c0be000-55d13c0bf000 /usr/local/bin/python3.8
# map: 55d13c0bf000-55d13c0c0000 /usr/local/bin/python3.8
# map: 55d13c0c0000-55d13c0c1000 /usr/local/bin/python3.8
# map: 55d13c0c1000-55d13c0c2000 /usr/local/bin/python3.8
# map: 55d13c0c2000-55d13c0c3000 /usr/local/bin/python3.8
# map: 7f01508b3000-7f01508b8000 /usr/local/lib/python3.8/site-packages/pandas/_libs/json.cpython-38-x86_64-linux-gnu.so
# map: 7f01508b8000-7f01508c4000 /usr/local/lib/python3.8/site-packages/pandas/_libs/json.cpython-38-x86_64-linux-gnu.so
# map: 7f01508c4000-7f01508c9000 /usr/local/lib/python3.8/site-packages/pandas/_libs/json.cpython-38-x86_64-linux-gnu.so
# map: 7f01508c9000-7f01508ca000 /usr/local/lib/python3.8/site-packages/pandas/_libs/json.cpython-38-x86_64-linux-gnu.so
# map: 7f01508ca000-7f01508cb000 /usr/local/lib/python3.8/site-packages/pandas/_libs/json.cpython-38-x86_64-linux-gnu.so

But I'm a beginner with this tool, so I don't really understand the relationship between austin and austinp and why austinp can print out those info.

[P403n1x87]

@Abeautifulsnow I'm trying to have a look at possible issues here. I'm testing with the latest docker and Austin and things seem to be working as expected when profiling a process within a container from the host. Could you please clarify your scenario a bit more, please? Are you running Austin within the same container of the running process, or are you also trying to profile from the host? Does Austin work with another Python process (e.g. just the REPL)? Thanks 🙏

[Abeautifulsnow]

@P403n1x87

Does Austin work with another Python process (e.g. just the REPL)?

Yes, austin works fine with REPL process, I can capture it by austin.

# austin -p 9143

...
P9143;T0:9143 170
P9143;T0:9143 170
^C
# duration: 582458

Statistics
⌛ Sampling duration : 0.58 s
⏱️  Frame sampling (min/avg/max) : 8/21/202 μs
🐢 Long sampling rate : 1/3345 (0.03 %) samples took longer than the sampling interval to collect
💀 Error rate : 0/3345 (0.00 %) invalid samples

# austin -w 9143
              _   _
 __ _ _  _ __| |_(_)_ _
/ _` | || (_-<  _| | ' \
\__,_|\_,_/__/\__|_|_||_| 3.6.0 [gcc 9.4.0]

🐍 Python version: 3.8.0


💤 Process 9143 🧵 Thread 0:9143

Are you running Austin within the same container of the running process, or are you also trying to profile from the host?

I am trying to profile from the host not container and the previous comment Oh, right, I discover that austinp command can print out some information from inside that docker container. is just a test to attempt to know where the problem is.

I also use it to capture other python services running in docker and also output nothing by profile from host. It's really so odd.

Do you have any other guesses or thoughts or else you want to know?

[P403n1x87]

@Abeautifulsnow many thanks for your help thus far. I have recently merged #217 to improve support for "containerised" processes. Would you be able to compile from sources from the devel branch and test whether the improvement solves this issue? 🙏 Otherwise my other hunch is that this might be due to something weird going on with uvicorn. I'll try to see if I can test with that when I get a chance.

[Abeautifulsnow]

@P403n1x87 Sorry for the late reply. I have compiled it from source and retested it as previously described. Unfortunately, it still does not work well.

# git branch
* devel
# ls -l
total 624
-rw-r--r-- 1 root root 21286 Apr   7 08:59 argparse.c
-rw-r--r-- 1 root root  2118 Apr   7 08:59 argparse.h
-rwxr-xr-x 1 root root 59080 Apr   7 09:02 austin
-rw-r--r-- 1 root root  3421 Apr   7 08:59 austin.1
-rw-r--r-- 1 root root  8952 Apr   7 09:02 austin-argparse.o
-rw-r--r-- 1 root root 17272 Apr   7 09:02 austin-austin.o
-rw-r--r-- 1 root root 10728 Apr   7 08:59 austin.c
-rw-r--r-- 1 root root  7536 Apr   7 09:02 austin-cache.o
-rw-r--r-- 1 root root  4104 Apr   7 09:02 austin-error.o
-rw-r--r-- 1 root root  1358 Apr   7 08:59 austin.h
-rw-r--r-- 1 root root 10192 Apr   7 09:02 austin-logging.o
-rw-r--r-- 1 root root  1880 Apr   7 09:02 austin-platform.o
-rw-r--r-- 1 root root  6576 Apr   7 09:02 austin-py_proc_list.o
-rw-r--r-- 1 root root 30728 Apr   7 09:02 austin-py_proc.o
-rw-r--r-- 1 root root 19304 Apr   7 09:02 austin-py_thread.o
-rw-r--r-- 1 root root  8184 Apr   7 09:02 austin-stats.o
-rw-r--r-- 1 root root  1573 Apr   7 08:59 bin.h
-rw-r--r-- 1 root root 13436 Apr   7 08:59 cache.c
-rw-r--r-- 1 root root 12947 Apr   7 08:59 cache.h
-rw-r--r-- 1 root root  1988 Apr   7 08:59 code.h
-rw-r--r-- 1 root root  2961 Apr   7 08:59 error.c
-rw-r--r-- 1 root root  3372 Apr   7 08:59 error.h
-rw-r--r-- 1 root root  6440 Apr   7 08:59 events.h
-rw-r--r-- 1 root root  7165 Apr   7 08:59 frame.h
-rw-r--r-- 1 root root  1278 Apr   7 08:59 heap.h
-rw-r--r-- 1 root root  1637 Apr   7 08:59 hints.h
drwxr-xr-x 2 root root   137 Apr   7 08:59 linux
-rw-r--r-- 1 root root  4638 Apr   7 08:59 logging.c
-rw-r--r-- 1 root root  3916 Apr   7 08:59 logging.h
drwxr-xr-x 2 root root    42 Apr   7 08:59 mac
-rw-r--r-- 1 root root 52326 Apr   7 09:02 Makefile
-rw-r--r-- 1 root root  1810 Apr   7 08:59 Makefile.am
-rw-r--r-- 1 root root 60114 Apr   7 09:01 Makefile.in
-rw-r--r-- 1 root root  7049 Apr   7 08:59 mem.h
-rw-r--r-- 1 root root  4171 Apr   7 08:59 mojo.h
-rw-r--r-- 1 root root  4211 Apr   7 08:59 msg.h
-rw-r--r-- 1 root root   967 Apr   7 08:59 platform.c
-rw-r--r-- 1 root root  2002 Apr   7 08:59 platform.h
-rw-r--r-- 1 root root 37197 Apr   7 08:59 py_proc.c
-rw-r--r-- 1 root root  5227 Apr   7 08:59 py_proc.h
-rw-r--r-- 1 root root  9553 Apr   7 08:59 py_proc_list.c
-rw-r--r-- 1 root root  3299 Apr   7 08:59 py_proc_list.h
-rw-r--r-- 1 root root  4006 Apr   7 08:59 py_string.h
drwxr-xr-x 2 root root   232 Apr   7 08:59 python
-rw-r--r-- 1 root root 31347 Apr   7 08:59 py_thread.c
-rw-r--r-- 1 root root  3165 Apr   7 08:59 py_thread.h
-rw-r--r-- 1 root root  4355 Apr   7 08:59 resources.h
-rw-r--r-- 1 root root  4666 Apr   7 08:59 stack.h
-rw-r--r-- 1 root root  5169 Apr   7 08:59 stats.c
-rw-r--r-- 1 root root  3160 Apr   7 08:59 stats.h
-rw-r--r-- 1 root root  1314 Apr   7 08:59 timer.h
-rw-r--r-- 1 root root  1547 Apr   7 08:59 timing.h
-rw-r--r-- 1 root root 12176 Apr   7 08:59 version.h
drwxr-xr-x 2 root root    42 Apr   7 08:59 win

# ./austin -p 3548 -C
              _   _
 __ _ _  _ __| |_(_)_ _
/ _` | || (_-<  _| | ' \
\__,_|\_,_/__/\__|_|_||_| 3.6.1 [gcc 4.8.5]

Parent process
👽 Not a Python process.

🚼 It looks like you are trying to profile a process that is not a Python
process, and that has not spawned any child Python processes. Make sure that
you are targeting the right application.

Otherwise my other hunch is that this might be due to something weird going on with uvicorn.

🤔I also test it with some services that are not started by uvicorn, they are flask applications that are launched directly through python without using any WSGI or ASGI servers such as uvicorn or others.

Furthermore, I execute a single py script(demo.py) in a running container which only print "test" inside while True clause. And the ./austin and py-spy prints are as belows:

# py-spy dump -p 31260
Process 31260: python3 demo.py
Python v3.8.18 (/usr/local/bin/python3.8)

Thread 0x7FD4A38E0B80 (active)
    <module> (demo.py:6)
# ./austin -p 31260 -C
              _   _
 __ _ _  _ __| |_(_)_ _
/ _` | || (_-<  _| | ' \
\__,_|\_,_/__/\__|_|_||_| 3.6.1 [gcc 4.8.5]

Parent process
👽 Not a Python process.

🚼 It looks like you are trying to profile a process that is not a Python
process, and that has not spawned any child Python processes. Make sure that
you are targeting the right application.

[P403n1x87]

@Abeautifulsnow thanks for testing the latest sources. We would have to look at the debug logs to get a better idea of what's going on. Would you perhaps be able to re-compile with debug logging support (-DDEBUG) and collect the output from /var/log/syslog? 🙏

[Abeautifulsnow]

@P403n1x87 Yeah, I can have a try on it. But I use

git clone --depth=1 https://github.com/P403n1x87/austin.git && cd austin
autoreconf --install
./configure
make
make install

to comile 🤦🏻 because an error occured when I ran this command(gcc -O3 -Os -Wall -pthread src/*.c -o src/austin) on my CentOS.. So can -DDEBUG be added in this way(use make)? And how👀?

[P403n1x87]

@Abeautifulsnow you can use ./configure --enable-debug-symbols true to enable debug with autotools, or do

gcc -g -pthread src/*.c -o src/austin -DDEBUG

[Abeautifulsnow]

@P403n1x87 ...I have compiled austin with this command,

autoreconf --install
./configure --enable-debug-symbols true
make
make install

but nothing is written to /var/log/syslog after execution ./austin -w 3020 -C.

# ll /var/log/syslog
-rw-rw-rw- 1 root root 0 Apr  11 17:36 /var/log/syslog

Am I using it incorrectly? 🥲

[P403n1x87]

🤔 maybe the rsyslog service is not running. Could you run systemctl start rsyslog?

[Abeautifulsnow]

🤔 maybe the rsyslog service is not running. Could you run systemctl start rsyslog?

🤔It's running well. But your /var/log/syslog is still empty. I google why and find out another file that maybe the one we want - /var/log/messages ...

In that file, I copy some texts here:

Apr 11 22:11:01 siact-11 systemd: Started Session 14985 of user root.
Apr 11 22:11:10 siact-11 austin[16262]: ====[ AUSTIN ]====
Apr 11 22:11:10 siact-11 journal: Suppressed 75 messages from /user.slice/user-0.slice
Apr 11 22:11:10 siact-11 austin[16262]: ELF binary has not all the mandatory Python symbols
Apr 11 22:11:10 siact-11 austin[16262]: Binary has no symbols
Apr 11 22:11:10 siact-11 austin[16262]: Cannot read remote memory
Apr 11 22:11:10 siact-11 austin[16262]: ELF binary has not all the mandatory Python symbols
Apr 11 22:11:10 siact-11 austin[16262]: Binary has no symbols
Apr 11 22:11:10 siact-11 austin[16262]: Cannot read remote memory
Apr 11 22:11:10 siact-11 austin[16262]: ELF binary has not all the mandatory Python symbols
Apr 11 22:11:10 siact-11 austin[16262]: Binary has no symbols
Apr 11 22:11:10 siact-11 austin[16262]: Cannot read remote memory
...
Apr 11 22:11:11 siact-11 austin[16262]: ELF binary has not all the mandatory Python symbols
Apr 11 22:11:11 siact-11 austin[16262]: Binary has no symbols
Apr 11 22:11:11 siact-11 austin[16262]: Cannot read remote memory
Apr 11 22:11:11 siact-11 austin[16262]: ELF binary has not all the mandatory Python symbols
Apr 11 22:11:11 siact-11 austin[16262]: Binary has no symbols
Apr 11 22:11:11 siact-11 austin[16262]: Cannot read remote memory
Apr 11 22:11:11 siact-11 austin[16262]: Cannot read remote memory
Apr 11 22:11:11 siact-11 austin[16262]: > Failed to copy BSS section
Apr 11 22:11:11 siact-11 austin[16262]: Failed to initialise process
Apr 11 22:11:11 siact-11 austin[16262]: > Cannot attach to running process.
Apr 11 22:11:11 siact-11 austin[16262]: Where mode on process 3020
Apr 11 22:11:11 siact-11 austin[16262]: Non-Python parent process has no Python children
Apr 11 22:12:01 siact-11 systemd: Started Session 14986 of user root.
Apr 11 22:12:53 siact-11 systemd-logind: New session 14987 of user root.
Apr 11 22:12:53 siact-11 systemd: Started Session 14987 of user root.

Are these logs that you want?

[P403n1x87]

Yes that's the expected output. Could you grep by austin a full run of the application so that we can try to figure out where we are failing to detect the Python interpreter? Thanks a lot for your assistance! 🙏

[Abeautifulsnow]

@P403n1x87 emmm. The log outputs I mentioned above is all. The symbol of ... is only ignoring the same outputs there. This means the full logs of run of the austin are those things. It does not seems like that is what you want? What should logs look like when austin run into an error? 🥲...

[P403n1x87]

@Abeautifulsnow I see, it looks like the log level is maybe set to something above info. Would you be able to set the log level to debug, please? 🙏