6

Consider this simple program (abort.py) that writes some text to stdout and stderr and then crashed (abort()).

import os
import sys

print("end stdout")
print("end stderr", file=sys.stderr)
os.abort()

When I run it in terminal, both output to stdout and stderr are correctly produced.

$ python3 abort.py 
end stdout
end stderr
Aborted (core dumped)

However, if I were to redirect stdout and/or stderr to another program (perhaps for logging purpose), it doesn't work any more.

$ python3 abort.py | cat
end stderr

$ python3 abort.py |& cat

$ python3 abort.py | tee -a logs
end stderr

$ python3 abort.py |& tee -a logs

# file `logs` is unchanged

In fact, if the program (abort.py) produce a lot of texts to stdout and stderr, only the last section of them is lost from the perspective of the receiving program on the other end of the pipe. I also tried running the program in a bash script and run that script, but the result is the same.

Why is this happening and how should I fix it?

Background

The example above is obviously contrived. The real world scenario is that I was debugging a large program that occasionally crash (segfault or aborted) after running for days. It produces a lot of logs to both stdout and stderr, but the most important piece of information regarding its crash (such as stack trace) is printed in the end right before the crash happens. I have a logging pipeline setup in a bash script (involves some tee and gzip for example), but I found that last section of the log saved is always missing, which is frustrating.

4
  • 3
    Because I see nothing in your code about buffering, I think it is the reason. You should start python with line buffering, or set stdout/stderr to line buffering (pipe override the default, so you should set it explicitly). the "flush" will handle data from the program to kernel (and the other program), before the flush the program own data, so if it crashes, the data are lost. Commented Dec 3, 2024 at 8:57
  • I don't think that's the problem. I also tried stdbuf -oL python3 abort.py |& cat which should enabled the line buffering for stdout, but it produces the exact same result
    – lewisxy
    Commented Dec 3, 2024 at 9:07
  • 1
    Yep, stdbuf doesn't seem to work with python3. It's possible that Python does its own buffering, distinct from the C library's logic which stdbuf tries to change. I think it's also possible for a program to change the buffering mode after stdbuf sets it, which also might make stdbuf ineffective.
    – ilkkachu
    Commented Dec 3, 2024 at 18:08
  • 1
    It's not only a pipe -- redirecting to a file >x or >&x also loses buffered output. (But it doesn't lose the reporting of the abnormal death, as the pipeline does, for the reason explained by icarus.) Standard-I/O on TCP socket(s) also do this, but is/are more finicky to set-up. Instead of stdbuf which as @ilkkachu says only tweaks stdlib, unbuffer (usually part of the expect package) creates a fake TTY (pseudo-TTY or PTY) that convinces nearly all programs including perl to not buffer more than a line. Commented Dec 4, 2024 at 3:04

1 Answer 1

13

This is a buffering "problem". Telling python not to buffer results in the desired result.

$ python3 -u abort.py |& cat
end stdout
end stderr

As to what to do about it, you should flush the output every time something is written that you care about enough to take the performance hit, e.g.

import os
import sys

print("end stdout", flush=True)
print("end stderr", file=sys.stderr, flush=True)
os.abort()

Note that the Aborted or Aborted (core dumped) messages come from the shell. If you are running bash or any other POSIX shell then the exit status of a pipeline is that of the end of the pipeline. As the cat is not aborting or dumping core you don't see a message. For bash, use set -o pipefail to see the aborted message:

$ set -o pipefail
$ python3 -u abort.py |& cat
end stdout
end stderr
Aborted (core dumped)
6
  • That's indeed the reason and good solutions for python, but probably not for the OP's "real ... large program that ... crash[es]" Commented Dec 4, 2024 at 3:08
  • @dave_thompson_085 I agree. However it is the best I can do given the lack of information about what is actually being run. It might be that it is a large single binary in which case running it under a better program than the shell (gdb comes to mind) which catches the segv and allows more inspection would provide insights.
    – icarus
    Commented Dec 4, 2024 at 4:58
  • You’re right. @dave_thompson_085 It’s a large c++ binary. I was too lazy to write an example in it when asking this question as I observed that the above Python program behaves similarly. I quickly checked my logging function in c++ and it does have std::endl in the end of each log line, which in theory should flush it, but it still loses log. Anyway, I will double check it and possibly open a question in stackoverflow if I can’t fix it myself
    – lewisxy
    Commented Dec 4, 2024 at 8:13
  • @icarus GDB is indeed a good choice, and it provides a lot more info. Thanks for bringing that up. My only concern is that whether it affects performance, since the binary I am debugging is somewhat performance sensitive and it won’t run in GDB in production. GDB does a lot more than just fork and exec the binary
    – lewisxy
    Commented Dec 4, 2024 at 8:19
  • Yes std::endl is specified to add a newline and flush, but it seems that it doesn't. Maybe since it is your logging function you could add an explicit flush()? Maybe you are stacking I/o on top of something and the flush is not making its way through all the stack (just wild speculation of course)? If your program doesn't create many threads or processes once it has been running for a few minutes then the overhead of running it under gdb should be low.
    – icarus
    Commented Dec 4, 2024 at 15:59

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.