Reputation: 798
I was debugging a really complex function (python function that calls some C++ modules from Boost/Python), and there's a print
or cout
or another similar function that I forgot to delete (can't seem to find it with grep), and now the program just keeps printing a bunch of 0s. Is there a way to tell which function was printing to the terminal, or is deleting the print statement one by one the only way? I'm on Fedora linux if that helps
Thanks
Upvotes: 2
Views: 1672
Reputation: 151
#!/usr/bin/env python3
'''
a simple program to stimulate writing terminal in multiple processes.
'''
prog name: ttywriter.py
import time
import sys
import multiprocessing
def print_stderr(s):
sys.stderr.write(f'{s}\n')
while True:
print("I'm writing to my terminal")
p = multiprocessing.Process(target=print_stderr,args=("I am a CPP program, writing to termianl",))
p.start()
time.sleep(1)
Pseudo terminal is usually opened as file descriptor 1 and 2. you can strace
them.
# tty
/dev/pts/0
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 2640 2427 0 07:07 pts/0 00:00:00 python3 ./ttywriter.py
# lsof -p `pgrep -f ttywriter` | grep pts
python3 2640 root 0u CHR 136,0 0t0 3 /dev/pts/0
python3 2640 root 1u CHR 136,0 0t0 3 /dev/pts/0
python3 2640 root 2u CHR 136,0 0t0 3 /dev/pts/0
# strace -s 65536 -e trace=write -e write=1,2 -fp `pgrep -f ttywriter`
strace: Process 2640 attached
write(1, "I'm writing to my terminal\n", 27) = 27
| 00000 49 27 6d 20 77 72 69 74 69 6e 67 20 74 6f 20 6d I'm writing to m |
| 00010 79 20 74 65 72 6d 69 6e 61 6c 0a y terminal. |
strace: Process 2695 attached
[pid 2695] write(2, "I am a CPP program, writing to termianl\n", 40) = 40
| 00000 49 20 61 6d 20 61 20 43 50 50 20 70 72 6f 67 72 I am a CPP progr |
| 00010 61 6d 2c 20 77 72 69 74 69 6e 67 20 74 6f 20 74 am, writing to t |
| 00020 65 72 6d 69 61 6e 6c 0a ermianl. |
[pid 2695] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2695, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
Upvotes: 0
Reputation: 2256
If printing happens from Python, setting up logger with elaborate formatters can help you precisely view the module, line number, func name, timestamp, etc.
Here's a sample formatter that I use in my project.
%(asctime)-s.%(msecs)03d %(levelname)-6.6s %(filename)-18.18s line:%(lineno)-4.4d %(funcName)-18s %(message)s
And the results:
2020-08-05 00:28:36.232 DEBUG connectionpool.py line:0959 _new_conn The fancy thing that gets printed.
2020-08-05 00:28:38.177 DEBUG connectionpool.py line:0437 _make_request This is your message but you have more info before this.
2020-08-05 00:28:38.180 DEBUG item.py line:0159 start_indexing Loggers with proper formatters can help you see
2020-08-05 00:28:38.180 DEBUG indexer.py line:0036 start Extensive information
Code:
import logging
import sys
LOGGER = logging.getLogger(__name__)
HANDLER = logging.StreamHandler(sys.stdout)
HANDLER.setFormatter(logging.Formatter("%(asctime)-s.%(msecs)03d %(levelname)-6.6s %(filename)-18.18s line:%(lineno)-4.4d %(funcName)-18s %(message)s"))
LOGGER.addHandler(HANDLER)
LOGGER.error("Here we go!")
Upvotes: 0
Reputation: 77847
I usually augment my complex designs with various forms of output tracing. The particular item that applies here is the trace_prefix. For instance:
TRACE = True
# TRACE = False # Uncomment this line for production runs.
def func(param):
trace_prefix = "TRACE func" if TRACE else ""
if TRACE:
print("ENTER", func, "param =", param)
...
print(trace_prefix, func_data)
...
This produces output I can identify by "grep TRACE", as well as picking out the stream from a given routine or package. This is easy enough to parameterize (grab the function name); I've done it with a decorator.
Upvotes: 1