classification
Title: logging.Handler.handleError regressed in python3
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: oren, vinay.sajip
Priority: normal Keywords:

Created on 2018-07-10 17:58 by oren, last changed 2018-08-01 05:44 by vinay.sajip. This issue is now closed.

Messages (8)
msg321391 - (view) Author: Oren (oren) Date: 2018-07-10 17:58
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'
msg321392 - (view) Author: Oren (oren) Date: 2018-07-10 18:01
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: ()
msg321466 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-11 14:43
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?
msg321482 - (view) Author: Oren (oren) Date: 2018-07-11 15:35
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?
msg321483 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-11 16:16
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.
msg321490 - (view) Author: Oren (oren) Date: 2018-07-11 17:18
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)
msg321494 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-11 18:57
> 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).
msg321509 - (view) Author: Oren (oren) Date: 2018-07-11 22:15
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?
History
Date User Action Args
2018-08-01 05:44:19vinay.sajipsetstatus: open -> closed
type: behavior
resolution: not a bug
stage: resolved
2018-07-11 22:15:08orensetmessages: + msg321509
2018-07-11 18:57:50vinay.sajipsetmessages: + msg321494
2018-07-11 17:18:05orensetmessages: + msg321490
2018-07-11 16:16:42vinay.sajipsetmessages: + msg321483
2018-07-11 15:35:29orensetmessages: + msg321482
2018-07-11 14:43:36vinay.sajipsetmessages: + msg321466
2018-07-11 14:32:24vinay.sajipsetversions: - Python 3.4, Python 3.5
2018-07-10 22:13:01orensetnosy: + vinay.sajip
2018-07-10 18:01:10orensetmessages: + msg321392
2018-07-10 17:58:52orencreate