Opened 9 months ago

Closed 6 months ago

#9099 defect closed duplicate (duplicate)

large quantity of mostly-useless error log events

Reported by: Jean-Paul Calderone Owned by:
Priority: normal Milestone:
Component: logger Keywords:
Cc: Branch:
Author:

Description

Using twist, most of my log output ends up being duplicates of a more-or-less useless "Unhandled error in Deferred" event:

{"log_namespace": "twisted.internet.defer", "log_level": {"__class_uuid__": "02e59486-f24d-46ad-8224-3acdf2a5732a", "name": "critical"}, "log_logger": {"unpersistable": true}, "log_format": "Unhandled error in Deferred:", "log_time": 1490885744.731011, "log_source": null, "isError": true}

This frequently comes up several hundred times in a row. This seems highly suspicious from a process which is doing very little work - eg, accepting one TCP connection and making one outgoing TCP connection every 15 seconds. By a recent count, each such spurt of activity resulted in 283 of these log events.

Attachments (1)

errors.txt (79.8 KB) - added by Jean-Paul Calderone 9 months ago.

Download all attachments as: .zip

Change History (4)

Changed 9 months ago by Jean-Paul Calderone

Attachment: errors.txt added

comment:1 Changed 8 months ago by Jean-Paul Calderone

Perhaps related is this behavior, though this may also just be another bug:

from sys import stdout
from twisted.logger import textFileLogObserver, globalLogPublisher
from twisted.python.failure import Failure
from twisted.internet.defer import fail

def main():
    try:
        1 / 0
    except:
        f = Failure()
    d = fail(f)
    del d

if __name__ == "__main__":
    globalLogPublisher.addObserver(textFileLogObserver(stdout))
    main()

producing this output:

Unhandled error in Deferred:
2017-04-24T08:01:38-0400 [twisted.internet.defer#critical] Unhandled error in Deferred:

2017-04-24T08:01:38-0400 [twisted.internet.defer#critical] 
        Traceback (most recent call last):
          File "debugging.py", line 16, in <module>
            main()
        --- <exception caught here> ---
          File "debugging.py", line 8, in main
            1 / 0
        exceptions.ZeroDivisionError: integer division or modulo by zero

Notice the doubled "Unhandled error in Deferred" reporting - with one given some kind of logging prefix and the other lacking it.

If no observer is explicitly added to the global log publisher then the output changes to:

Unhandled error in Deferred:

comment:2 Changed 8 months ago by Jean-Paul Calderone

Or maybe that's not related at all. The duplication appears to arise from the use of globalLogPublisher.addObserver instead of globalLogBeginner.beginLoggingTo.

This mistake brought to you by the backwards order of http://twistedmatrix.com/documents/current/core/howto/logger.html#the-global-log-publisher and http://twistedmatrix.com/documents/current/core/howto/logger.html#starting-the-global-log-publisher in the documentation (introducing addObserver first and then relying on folks to keep reading after they think they have the answer to find out that beginLoggingTo is actually the answer).

comment:3 Changed 6 months ago by Jean-Paul Calderone

Resolution: duplicate
Status: newclosed

This seems to be a duplicate of a *two year old bug*!

https://twistedmatrix.com/trac/ticket/7927

Note: See TracTickets for help on using tickets.