logging.Handler.handleError regressed in python3

[OrenLeaffer]

BPO	34086
Nosy	@vsajip, @OrenLeaffer

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2018-08-01.05:44:19.656>
created_at = <Date 2018-07-10.17:58:52.981>
labels = ['3.7', '3.8', 'type-bug', 'library', 'invalid']
title = 'logging.Handler.handleError regressed in python3'
updated_at = <Date 2018-08-01.05:44:19.655>
user = 'https://github.com/OrenLeaffer'

bugs.python.org fields:

activity = <Date 2018-08-01.05:44:19.655>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2018-08-01.05:44:19.656>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-07-10.17:58:52.981>
creator = 'oren'
dependencies = []
files = []
hgrepos = []
issue_num = 34086
keywords = []
message_count = 8.0
messages = ['321391', '321392', '321466', '321482', '321483', '321490', '321494', '321509']
nosy_count = 2.0
nosy_names = ['vinay.sajip', 'oren']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34086'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[OrenLeaffer]

In python2, calling Handler.handleError may not be strictly correct, but it doesn't raise an exception. However, this has regressed since this patch:
https://hg.python.org/cpython/rev/d7b868cdd9bb

$ cat logbug.py
import logging

class CustomHandler(logging.Handler):
    def transmit(self, record):
        return False
    def emit(self, record):
        if not self.transmit(record):
            self.handleError(record)
def main():
    logger = logging.getLogger()
    logger.addHandler(CustomHandler())
    logger.warning('this will work in python 2.7, but not 3')

if __name__ == '__main__':
    main()

$ python2 logbug.py
None
Logged from file logbug.py, line 15

$ python3 logbug.py
--- Logging error 

---

NoneType: None
Call stack:
Traceback (most recent call last):
  File "logbug.py", line 20, in <module>
    main()
  File "logbug.py", line 15, in main
    logger.warning('this will work in python 2.7, but not 3')
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 1318, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 1442, in _log
    self.handle(record)
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 1452, in handle
    self.callHandlers(record)
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 1514, in callHandlers
    hdlr.handle(record)
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 863, in handle
    self.emit(record)
  File "logbug.py", line 9, in emit
    self.handleError(record)
  File "/usr/local/opt/python3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 920, in handleError
    frame = tb.tb_frame
AttributeError: 'NoneType' object has no attribute 'tb_frame'

[OrenLeaffer]

I realize that there is a legitimate argument that handleError() is being used wrong in the example, but since it used to work, it'd be nice if it still did. I came across this after converting a codebase to python3 and it took a while for this problem to appear.

I propose the following fix:

$ git diff
diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index 29a7d46..f2c3023 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -908,7 +908,7 @@ class Handler(Filterer):
                 sys.stderr.write('Call stack:\n')
                 # Walk the stack frame up until we're out of logging,
                 # so as to print the calling context.
-                frame = tb.tb_frame
+                frame = tb and tb.tb_frame
                 while (frame and os.path.dirname(frame.f_code.co_filename) ==
                        __path__[0]):
                     frame = frame.f_back

This results in:
$ python3 logbug.py
--- Logging error ---
NoneType: None
Call stack:
Logged from file logbug.py, line 15
Message: 'this will work in python 2.7, but not 3'
Arguments: ()

[vsajip]

It seems innocuous enough, but the documentation for handleError() does say: "This method should be called from handlers when an exception is encountered during an emit() call."

That documentation is the same for 2.x and 3.x. This is not how you are using it. What happens if you just raise an Exception from your transmit() method, and just call transmit() from within emit() without making a condition of the return value?

[OrenLeaffer]

I totally agree that this involves misusing handleError. I ended up fixing the code that originally caused the problem, since it was wrong in the first place.

The reason I filed this bug and that I think it's worth fixing is that in previous versions, the problem would be that something might not get logged as expected; now the problem turns into a crash.

Not only is it now a crash, but the code that crashes requires something else to go wrong (we're not calling handleError() because everything went right), which means that applications that previously tolerated something going wrong, now break.

If the necessary fix was complicated, I could see the wisdom in not fixing it, but since it's simple, why not?

[vsajip]

For the crash to occur, it would have to be a handleError() called wrongly, when something didn't apparently go wrong (i.e. a call from outside an exception handling clause). So I'm not sure I follow your logic.

I agree the change you propose is simple, but that's an orthogonal concern, IMO.

[OrenLeaffer]

The code that was causing this problem looked something like:

--
def emit(self, record):
...
response = requests.post(...)
if not response.ok:
self.handleError(record)
...

In this case, something does apparently go wrong, but it doesn't actually involve an exception.

I assume that I'm not the only person in the world dealing with a code base where handleError was misused like this.

Here's some evidence that this is true: https://www.programcreek.com/python/example/619/logging.Handler (search for handleError in the page)

[vsajip]

Here's some evidence that this is true

I'm not sure that's evidence. That example page you linked to has 4 instances of handleError: 2 are definitions of overrides, and the other two are calls to the superclass method from those overriding methods, which would execute in an exception context if the subclass called handleError() correctly (i.e. from an exception handler).

[OrenLeaffer]

You're right - I misread those examples, sorry about that. It looks like my former colleague may have invented the bad code in question.

I'm ok with closing as "not a bug" - I do think not fixing it adds a small potential friction for people upgrading their version of python, but maybe raising an exception is an improvement over silently doing the wrong thing?