Opened 6 years ago

Closed 5 years ago

#3289 regression closed fixed (fixed)

startLoggingWithObserver IndexError

Reported by: gtaylor Owned by:
Priority: high Milestone:
Component: core Keywords:
Cc: exarkun Branch: branches/logging-recursion-3289
(diff, github, buildbot, log)
Author: jml Launchpad Bug:

Description

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?

Attachments (3)

minimal.tac (187 bytes) - added by exarkun 6 years ago.
minimal reproduction of the problem
broken-logging.tac (413 bytes) - added by glyph 6 years ago.
A new version of minimal.tac which opens a failsafe log to observe the traceback that the main log observer produces.
really-minimal.py (373 bytes) - added by glyph 6 years ago.
A really minimal example, which doesn't involve twistd, and just shows you the full 'maximum recursion depth exceeded' traceback.

Download all attachments as: .zip

Change History (16)

comment:1 Changed 6 years ago by 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.

Changed 6 years ago by exarkun

minimal reproduction of the problem

comment:2 Changed 6 years ago by 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.

comment:3 Changed 6 years ago by exarkun

  • Cc exarkun added

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.

comment:4 Changed 6 years ago by 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?

comment:5 Changed 6 years ago by 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).

comment:6 Changed 6 years ago by 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.

Changed 6 years ago by glyph

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

Changed 6 years ago by glyph

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

comment:7 Changed 5 years ago by jml

  • Author set to jml
  • Branch set to branches/logging-recursion-3289

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

comment:8 Changed 5 years ago by jml

  • Keywords review added
  • Owner glyph deleted

comment:9 Changed 5 years ago by therve

  • Keywords review removed
  • Owner set to jml

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.

comment:10 Changed 5 years ago by jml

  • Keywords review added
  • Owner changed from jml to therve

comment:11 Changed 5 years ago by therve

  • Keywords review removed
  • Owner changed from therve to jml

+1!

comment:12 Changed 5 years ago by jml

  • Resolution set to fixed
  • Status changed from new to closed

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

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

comment:13 Changed 4 years ago by <automation>

  • Owner jml deleted
Note: See TracTickets for help on using tickets.