startLoggingWithObserver IndexError

[gtaylor]

I'm getting the following error when trying to start an older server app that used the previous major revision of Twisted. I couldn't find anything in the release notes about a backwards-incompatible change that would break things, but perhaps I missed something:

2008-06-10 08:21:31-0400 [-] Log opened.
2008-06-10 08:21:31-0400 [-] --------------------------------------------------
2008-06-10 08:21:31-0400 [-]  Command Aliases Loaded: 9
2008-06-10 08:21:31-0400 [-]  Evennia Test Site started on port(s):
2008-06-10 08:21:31-0400 [-]   * 4000
2008-06-10 08:21:31-0400 [-] --------------------------------------------------
2008-06-10 08:21:31-0400 [-] Loaded.
2008-06-10 08:21:31-0400 [-] Traceback (most recent call last):
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\scripts\twistd.py", line 21, in <module>
2008-06-10 08:21:31-0400 [-]     run()
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\scripts\twistd.py", line 27, in run
2008-06-10 08:21:31-0400 [-]     app.run(runApp, ServerOptions)
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\application\app.py", line 614, in run
2008-06-10 08:21:31-0400 [-]     runApp(config)
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\scripts\twistd.py", line 23, in runApp
2008-06-10 08:21:31-0400 [-]     _SomeApplicationRunner(config).run()
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\application\app.py", line 335, in run
2008-06-10 08:21:31-0400 [-]     self.startLogging(self.getLogObserver())
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\application\app.py", line 367, in startLogging
2008-06-10 08:21:31-0400 [-]     log.startLoggingWithObserver(observer)
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\python\log.py", line 519, in startLoggingWithObserver
2008-06-10 08:21:31-0400 [-]     msg("Log opened.")
2008-06-10 08:21:31-0400 [-]   File "C:\Python25\Lib\site-packages\twisted\python\log.py", line 246, in msg
2008-06-10 08:21:31-0400 [-]     o = self.observers.pop(i)
2008-06-10 08:21:31-0400 [-] IndexError: pop index out of range

The root Python file for the project is at:  http://code.google.com/p/evennia/source/browse/trunk/server.py

The startup script is at:  http://code.google.com/p/evennia/source/browse/trunk/startup.bat?r=274

Regression? Bug?

[exarkun]

This seems to be due to server.py initializing logging itself, including clobbering sys.stdout (since it does not pass False for the setStdout parameter of log.startLogging). With the -n command line argument, twistd then also tries to initialize logging, including clobbering sys.stdout. The interaction between these two results in infinite recursion in the logging system (although the exact reason for this is tricky to debug, since stdout has been well and truly mangled). Infinite recursion results in an error in a random place which probably results in the logging system trying to remove what it has decided is a buggy log observer (there's another ticket open for fixing this behavior).

If you run without -n, then things seem to work fine. However, I'd recommend removing the startLogging call from EvenniaService.__init__. It's the job of twistd to handle logging; application code shouldn't be touching that stuff. You can specify which logfile to use with the --logfile option to twistd. We're also working on a way for .tac files (server.py is really a .tac file - it should probably be renamed to reflect this) to specify the log file name programmatically so, so you could continue to load it from your settings module.

It's not clear to me why this worked in any previous version of Twisted; it was probably accidental. It may be worth fixing this behavior so that two startLogging calls that set stdout again work, but it's a pretty severe corner case.

[exarkun]

minimal reproduction of the problem

[exarkun]

Okay, here's how the infinite recursion happens.

The first startLogging call creates a new log observer which writes to sys.stdout, which is at this point the real stdout object. It also replaces sys.stdout with StdioOnnaStick which handles calls to its write method by emitting a log message.

The second startLogging call creates a new log observer which writes to sys.stdout, which at this point is the StdioOnnaStick instance. It also replaces sys.stdout with another StdioOnnaStick instance.

This second log observer is terminally defective. It handles log events by emitting log events, resulting in infinite recursion, and the traceback the attached example produces.

[exarkun]

In 8.1, the tac file is executed before twistd calls startLogging. It creates an observer which refers to the file it gives and replaces sys.stdout with a StdioOnnaStick instance. twistd then calls startLogging which creates an observer which refers to the StdioOnnaStick instance.

In 2.5, twistd calls startLogging before it executes the tac file. It creates an observer which refers to the real stdout object and replaces sys.stdout with a StdioOnnaStick instance. Then the tac file calls startLogging, but it creates an observer which refers to the given file. The value of sys.stdout is irrelevant at this point, because the tac file doesn't use it.

So that's why it's broken in 8.1 and works in 2.5.

[gtaylor]

I see that -n is now deprecated (for backward compatibility). Running without it is fine, but does that kill my ability to daemonize? Does it only daemonize now if you give it a logfile other than stdout?

[exarkun]

Where did you see that -n is deprecated? Are you sure you didn't confuse it with the help for -q?

-n is short for --nodaemon and prevents daemonization. If you don't specify it, twistd will daemonize (and then you can't specify stdout as the logfile). The logfile you specify won't have any effect on whether twistd daemonizes or not (except for the previous parenthetical).

[exarkun]

Log observers which raise an exception are no longer removed, so this problem will manifest differently now, but it's still a problem, I think.

[glyph]

A new version of minimal.tac which opens a failsafe log to observe the traceback that the main log observer produces.

[glyph]

A really minimal example, which doesn't involve twistd, and just shows you the full 'maximum recursion depth exceeded' traceback.

[jml]

(In [28238]) Branching to 'logging-recursion-3289'

[therve]

So it looks like the branch breaks the way trial interacts with logging? It should probably be fixed before merging the branch. Otherwise the change looks sane, I guess.

[therve]

+1!

[jml]

(In [28266]) Fix infinite recursion error that occurs when calling startLogging twice.

• Author: jml
• Reviewer: therve
• Fixes #3289