Opened 2 years ago

Closed 6 months ago

#8086 defect closed duplicate (duplicate)

twisted.logger.jsonFileLogObserver does not record tracebacks from unhandled errors in collected Deferreds

Reported by: Colin Dunklau Owned by: Colin Dunklau
Priority: normal Milestone:
Component: logger Keywords:
Cc: colin.dunklau@… Branch:
Author: cdunklau

Description

While textFileLogObserver dumps the traceback, jsonFileLogObserver does not. The attached code demonstrates the issue.

Attachments (9)

error.py (962 bytes) - added by Colin Dunklau 2 years ago.
errorout.txt (1.7 KB) - added by Colin Dunklau 2 years ago.
error_simplified.py (865 bytes) - added by Colin Dunklau 2 years ago.
Simplified without task.react
log_jsonobserver.txt (1.5 KB) - added by Colin Dunklau 2 years ago.
Demonstration of the original problem
log_textobserver.txt (1.3 KB) - added by Colin Dunklau 2 years ago.
Demonstration showing problem does not affect text observer
log_jsonobserver_deferred_logging.txt (35.3 KB) - added by Colin Dunklau 2 years ago.
deferred debugging causes the traceback to be dumped directly to the log or stdout/err
test_to_reproduce_8086.diff (1.0 KB) - added by Colin Dunklau 2 years ago.
test_to_reproduce_8086.2.diff (1.0 KB) - added by Colin Dunklau 2 years ago.
fix-8086.diff (1.2 KB) - added by Colin Dunklau 2 years ago.
My proposed fix with a test

Download all attachments as: .zip

Change History (24)

Changed 2 years ago by Colin Dunklau

Attachment: error.py added

Changed 2 years ago by Colin Dunklau

Attachment: errorout.txt added

Changed 2 years ago by Colin Dunklau

Attachment: error_simplified.py added

Simplified without task.react

Changed 2 years ago by Colin Dunklau

Attachment: log_jsonobserver.txt added

Demonstration of the original problem

Changed 2 years ago by Colin Dunklau

Attachment: log_textobserver.txt added

Demonstration showing problem does not affect text observer

Changed 2 years ago by Colin Dunklau

deferred debugging causes the traceback to be dumped directly to the log or stdout/err

comment:1 Changed 2 years ago by Colin Dunklau

Owner: set to Colin Dunklau
Status: newassigned

comment:2 Changed 2 years ago by Colin Dunklau

Cc: colin.dunklau@… added
Summary: twisted.logger.jsonFileLogObserver does not record tracebacks from Failurestwisted.logger.jsonFileLogObserver does not record tracebacks from unhandled errors in collected Deferreds

comment:3 Changed 2 years ago by Colin Dunklau

Okay, i'm getting somewhere. Adding an observer to get the events directly and write the repr to a file, a new event shows up:

{
    'log_namespace': 'twisted.logger._observer',
    'log_level': <LogLevel=critical>,
    'observer': <twisted.logger._file.FileLogObserver object at 0x7fb1fcbc6250>,
    'log_source': None,
    'log_logger': <Logger 'twisted.logger._observer'>,
    'log_time': 1446731370.387473,
    'log_format': 'Temporarily disabling observer {observer} due to exception: {log_failure}',
    'log_failure': <twisted.python.failure.Failure exceptions.AttributeError: 'NoneType' object has no attribute '_formatter_parser'>
}

So it appears that the observer or some code it calls is broken.

Edit: the event that appears to cause the issue:

{
    'log_namespace': 'twisted.internet.defer',
    'log_level': <LogLevel=critical>,
    'debugInfo': '',
    'log_source': None,
    'log_logger': <Logger 'twisted.internet.defer'>,
    'log_time': 1446731370.38742,
    'log_format': None,
    'log_failure': <twisted.python.failure.Failure exceptions.Exception: break stuff now>
}
Last edited 2 years ago by Colin Dunklau (previous) (diff)

Changed 2 years ago by Colin Dunklau

Attachment: test_to_reproduce_8086.diff added

Changed 2 years ago by Colin Dunklau

comment:4 Changed 2 years ago by Colin Dunklau

The test in the just-attached patch (both, i'm stupid and attached it twice) reproduces the issue, resulting in the traceback:

Traceback (most recent call last):
  File "/home/cdunklau/Development/Twisted/twisted/logger/test/test_json.py", line 301, in test_observerDoesntFailWithWhatever
    observer(event)
  File "/home/cdunklau/Development/Twisted/twisted/logger/_file.py", line 50, in __call__
    text = self.formatEvent(event)
  File "/home/cdunklau/Development/Twisted/twisted/logger/_json.py", line 245, in <lambda>
    lambda event: u"{0}{1}\n".format(recordSeparator, eventAsJSON(event))
  File "/home/cdunklau/Development/Twisted/twisted/logger/_json.py", line 196, in eventAsJSON
    flattenEvent(event)
  File "/home/cdunklau/Development/Twisted/twisted/logger/_flatten.py", line 87, in flattenEvent
    aFormatter.parse(event["log_format"])
  File "/usr/lib/python2.7/string.py", line 615, in parse
    return format_string._formatter_parser()
exceptions.AttributeError: 'NoneType' object has no attribute '_formatter_parser'

So it appears that the twisted.logger._flatten assumes the event's "log_format" key will refer to a string, but somewhere in the logger lib or in t.i.defer, the event's "log_format" key refers to None.

comment:5 Changed 2 years ago by Colin Dunklau

Since the howto doc for twisted.logger asserts that the log_format key may be None, the bug appears to indeed be in how twisted.logger._flatten.flattenEvent handles the None case, or rather that it doesn't handle it.

comment:6 Changed 2 years ago by Colin Dunklau

This is related to #7927 and damn SpamBayes to hell if it rejects my comment again

Changed 2 years ago by Colin Dunklau

Attachment: fix-8086.diff added

My proposed fix with a test

comment:7 Changed 2 years ago by Colin Dunklau

Author: cdunklau
Keywords: review added
Owner: changed from Colin Dunklau to Glyph
Status: assignednew

This patch at least makes the original demonstration code print a traceback without deferred debugging on while using the json observer... but I expected it to actually log the traceback as part of an entry, not just dump the traceback in the log without a JSON wrapper.

I have no idea what to do next.

Assigning to glyph because he volunteered out of embarrassment :)

comment:8 Changed 2 years ago by Colin Dunklau

I found where it's happening. FileLogObserver.__call__ just appends the traceback to the output line it got from the formatter. Shouldn't this functionality be the formatter's job, not the observer's?

Last edited 2 years ago by Colin Dunklau (previous) (diff)

comment:9 Changed 2 years ago by Adi Roiban

Keywords: review removed
Owner: changed from Glyph to Colin Dunklau

Hi cdunklau

Can you please write a unit test demonstrating the error and the expected behaviour?

The title of this ticket talks about twisted.logger.jsonFileLogObserver but in your latest patch I can only see changes/tests in flattenEvent

Can you please update the title and description of this ticket to match the attached patch?

The documentation api-docs + narrative should describe the expected behaviour.

In case it does not do it, please also update the docs to what do you think should be the "right behaviour" and the one matching the latest patch.

Thanks!

comment:10 Changed 14 months ago by Julian Berman

Milestone: New Logging System

comment:11 Changed 12 months ago by Wilfredo Sánchez Vega

Component: corelogger

comment:12 Changed 12 months ago by Colin Dunklau

The problem in flattenEvent is a separate issue, covered by #8860. I need to continue investigating the original problem, that is, that unhandled deferred failures do not provoke a log entry containing the traceback.

comment:13 in reply to:  8 Changed 12 months ago by Colin Dunklau

With the fix in my PR for #8860, I cannot reproduce the problem with jsonFileLogObserver.

This comment of mine confused me, since I couldn't find the code anymore... Colin Dunklau:

I found where it's happening. FileLogObserver.__call__ just appends the traceback to the output line it got from the formatter. Shouldn't this functionality be the formatter's job, not the observer's?

...however the mentioned code was moved out of FileLogObserver.__call__ in the fix for #8858

So, once #8860 is closed, this issue can be closed as well.

comment:14 Changed 11 months ago by Wilfredo Sánchez Vega

Milestone: New Logging System

Closing New Logging System milestone; use logger component for ongoing tickets.

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

Resolution: duplicate
Status: newclosed
Note: See TracTickets for help on using tickets.