945706 - [mozlog] logger.exception() calls do not add exception information to the output

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The following code should give a verbose output about the exception thrown. But with mozlog I can only see a single line compared to a normal logger from the logging module:

Code:
=====

import logging
import mozprofile
import mozlog

try:
    mozprofile.aaa()
except Exception, e:
    logging.basicConfig(level=logging.INFO)
    logger = logging.getLogger(__name__)
    logger.exception(str(e))

    logging.basicConfig(level=logging.INFO)
    logger = mozlog.getLogger('root')
    logger.exception(str(e))


Output:
=======

ERROR:__main__:'module' object has no attribute 'aaa'
Traceback (most recent call last):
  File "test_addons.py", line 7, in <module>
    mozprofile.aaa()
AttributeError: 'module' object has no attribute 'aaa'
root ERROR | 'module' object has no attribute 'aaa'

It looks like that mozlog does not correctly inherit the right settings.

Comment 1

[Julien Pagès (:parkouss)]

Attachment: logger.exception() calls do not add exception information to the output

Hi,

William I assigned you for the review I hope it's OK.

In fact the problem comes from the formatter used, MozFormatter. The base method Formatter.format handle the formatting of the exception, but this it not done by MozFormatter.format.

I choosed to use the *protected* member (self._fmt) and call the base Formatter.format method instead of copy/paste of the base code. I believe this *protected* member may be used when subclassing logging.Formatter.

The output of Henrik's example is now:

ERROR:__main__:'module' object has no attribute 'aaa'
Traceback (most recent call last):
  File "mylog.py", line 7, in <module>
    mozprofile.aaa()
AttributeError: 'module' object has no attribute 'aaa'
root ERROR | 'module' object has no attribute 'aaa'
Traceback (most recent call last):
  File "mylog.py", line 7, in <module>
    mozprofile.aaa()
AttributeError: 'module' object has no attribute 'aaa'

Also I replaced the include_timestamp logic, and I tested it - time formatting is working and similar:

2014-10-25 17:20:59,212 root ERROR | 'module' object has no attribute 'aaa'
Traceback (most recent call last):
  File "mylog.py", line 7, in <module>
    mozprofile.aaa()
AttributeError: 'module' object has no attribute 'aaa'

Comment 2

[William Lachance (:wlach)]

Comment on attachment 8511523 [details] [diff] [review]
logger.exception() calls do not add exception information to the output

This makes sense to me, although we are deprecating mozlog itself, it probably makes sense to make it work better for those still using it. CC'ing :ahal for additional feedback which I'd like to see before pushing.

Comment 3

[Andrew Halberstadt [:ahal]]

Comment on attachment 8511523 [details] [diff] [review]
logger.exception() calls do not add exception information to the output

Review of attachment 8511523 [details] [diff] [review]:
-----------------------------------------------------------------

Makes sense to me, thanks!

Comment 4

[Julien Pagès (:parkouss)]

Should I add the checkin-needed keyword ?

Comment 5

[William Lachance (:wlach)]

(In reply to Julien Pagès from comment #4)
> Should I add the checkin-needed keyword ?

Normally the sheriffs insist on a try run for checkin-needed. I ran some quick tests locally and after verifying that mozlog was still working as expected pushed it myself:

https://hg.mozilla.org/integration/mozilla-inbound/rev/5563cb631fb9

If you haven't already, you should definitely sign up for try access so you can submit try jobs:

https://www.mozilla.org/en-US/about/governance/policies/commit/

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/5563cb631fb9