Here's a simple Python script:
import subprocess
with open('hi.txt', 'w') as f:
subprocess.Popen(['echo', 'Hello'], stdout=f).wait()
Here's what it does:
$ python2.7 hi.py
$ cat hi.txt
Hello
And here's what happens if you try to use the trace module to trace the
execution:
$ python2.7 -m trace --trace hi.py
(lots of trace output omitted)
So far so good, but take a look at hi.txt:
$ cat hi.txt
subprocess.py(1170): _dup2(errwrite, 2)
--- modulename: subprocess, funcname: _dup2
subprocess.py(1164): if a == b:
subprocess.py(1166): elif a is not None:
... 154 lines of unexpected trace output omitted ...
os.py(379): try:
os.py(380): func(fullname, *argrest)
Hello
The tracing hook installed by trace.py survives the os.fork() and interferes
with subprocess output redirection. Now you know.
Imagine what this does to scripts that execute shell commands and try to
parse their output.
Who wants to file a
bug and/or provide a patch? I'm afraid I don't have enough round
tuits...
If you use
logging.config.fileConfig
(e.g. because you use paster serve something.ini to deploy your WSGI
apps) you should know about this.
By default fileConfig disables all pre-existing loggers
if they (or their parent loggers) are not explicitly mentioned in your
.ini file.
This can result in unintuitive behaviour:
(if you don't see the embedded example, you can find it at https://gist.github.com/1642893).
If you have Python 2.6 or later (and you should), you can turn this off
by passing disable_existing_loggers=False to fileConfig().
But what if it's not you calling fileConfig() but your framework (e.g.
the above-mentioned paster serve)?
Now usually paster serve tries to configure logging before
importing any of your application modules, so there should be no pre-existing
loggers to disable. Sometimes, however, this doesn't work for one reason or
another, and you end up with your production server suppressing warnings and
errors that should not be suppressed. I haven't actually figured out yet who's
responsible for those early imports in the application I'm working on (until
today I assumed, incorrectly, that paster imports the module containing your
WSGI app before it calls fileConfig).
If you're not sure if this bug can bite you or not, check that you don't
have any disabled loggers by doing something like
import logging
assert not any(getattr(logger, 'disabled', False)
for logger in logging.getLogger().manager.loggerDict.values())
while your application is running.
