Issue38921
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2019-11-26 18:39 by joy, last changed 2022-04-11 14:59 by admin. This issue is now closed.
Files | ||||
---|---|---|---|---|
File name | Uploaded | Description | Edit | |
logging_test_script.py | joy, 2020-01-14 20:44 | Test script |
Messages (7) | |||
---|---|---|---|
msg357523 - (view) | Author: Joy (joy) * | Date: 2019-11-26 18:39 | |
Seeing an issue with the logger fmt not setting correctly in the Handler class. Our code calls format many times which works for a while and then we receive the following errors: [3206] 2019/11/26 12:42:31.011> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1725, in info [3206] 2019/11/26 12:42:31.013> [ERROR] self.log(INFO, msg, *args, **kwargs) [3206] 2019/11/26 12:42:31.014> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1763, in log [3206] 2019/11/26 12:42:31.016> [ERROR] self.logger.log(level, msg, *args, **kwargs) [3206] 2019/11/26 12:42:31.017> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1444, in log [3206] 2019/11/26 12:42:31.018> [ERROR] self._log(level, msg, args, **kwargs) [3206] 2019/11/26 12:42:31.019> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1514, in _log [3206] 2019/11/26 12:42:31.021> [ERROR] self.handle(record) [3206] 2019/11/26 12:42:31.022> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1524, in handle [3206] 2019/11/26 12:42:31.024> [ERROR] self.callHandlers(record) [3206] 2019/11/26 12:42:31.025> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1586, in callHandlers [3206] 2019/11/26 12:42:31.026> [ERROR] hdlr.handle(record) [3206] 2019/11/26 12:42:31.027> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 894, in handle [3206] 2019/11/26 12:42:31.029> [ERROR] self.emit(record) [3206] 2019/11/26 12:42:31.029> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1127, in emit [3206] 2019/11/26 12:42:31.031> [ERROR] StreamHandler.emit(self, record) [3206] 2019/11/26 12:42:31.032> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 1025, in emit [3206] 2019/11/26 12:42:31.033> [ERROR] msg = self.format(record) [3206] 2019/11/26 12:42:31.035> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 869, in format [3206] 2019/11/26 12:42:31.036> [ERROR] return fmt.format(record) [3206] 2019/11/26 12:42:31.037> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 869, in format [3206] 2019/11/26 12:42:31.039> [ERROR] return fmt.format(record) [3206] 2019/11/26 12:42:31.040> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 869, in format [3206] 2019/11/26 12:42:31.041> [ERROR] return fmt.format(record) [3206] 2019/11/26 12:42:31.042> [ERROR] [Previous line repeated 978 more times] [3206] 2019/11/26 12:42:31.043> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 608, in format [3206] 2019/11/26 12:42:31.045> [ERROR] record.message = record.getMessage() [3206] 2019/11/26 12:42:31.046> [ERROR] File "/usr/lib/python3.7/logging/__init__.py", line 367, in getMessage [3206] 2019/11/26 12:42:31.048> [ERROR] msg = str(self.msg) [3206] 2019/11/26 12:42:31.049> [ERROR] RecursionError [3206] 2019/11/26 12:42:31.049> [ERROR] : [3206] 2019/11/26 12:42:31.050> [ERROR] maximum recursion depth exceeded while calling a Python object I believe after a while the fmt object is not being set correctly and ends up calling the Handler's format function again and again. |
|||
msg357526 - (view) | Author: Karthikeyan Singaravelan (xtreak) * | Date: 2019-11-26 19:29 | |
Can you please attach a simple script to reproduce the issue? |
|||
msg357904 - (view) | Author: Vinay Sajip (vinay.sajip) * | Date: 2019-12-06 07:25 | |
I'll flag this as pending, and close in a week if no minimal needed-to-reproduce script is posted. Let me know if you are working on producing such a minimal script and need more time. |
|||
msg358286 - (view) | Author: Joy (joy) * | Date: 2019-12-12 03:24 | |
Yes, still working on a script for this bug. |
|||
msg359992 - (view) | Author: Joy (joy) * | Date: 2020-01-14 20:44 | |
This script should produce the following error: Traceback (most recent call last): File "logging_test_script.py", line 70, in <module> testobj.main() File "logging_test_script.py", line 62, in main Logger.main_logger.info('Adding a line into {}'.format(source)) File "/usr/lib/python3.7/logging/__init__.py", line 1378, in info self._log(INFO, msg, args, **kwargs) File "/usr/lib/python3.7/logging/__init__.py", line 1514, in _log self.handle(record) File "/usr/lib/python3.7/logging/__init__.py", line 1524, in handle self.callHandlers(record) File "/usr/lib/python3.7/logging/__init__.py", line 1586, in callHandlers hdlr.handle(record) File "/usr/lib/python3.7/logging/__init__.py", line 894, in handle self.emit(record) File "/usr/lib/python3.7/logging/__init__.py", line 1127, in emit StreamHandler.emit(self, record) File "/usr/lib/python3.7/logging/__init__.py", line 1025, in emit msg = self.format(record) File "/usr/lib/python3.7/logging/__init__.py", line 869, in format return fmt.format(record) File "/usr/lib/python3.7/logging/__init__.py", line 869, in format return fmt.format(record) File "/usr/lib/python3.7/logging/__init__.py", line 869, in format return fmt.format(record) [Previous line repeated 984 more times] File "/usr/lib/python3.7/logging/__init__.py", line 609, in format if self.usesTime(): File "/usr/lib/python3.7/logging/__init__.py", line 577, in usesTime return self._style.usesTime() File "/usr/lib/python3.7/logging/__init__.py", line 419, in usesTime return self._fmt.find(self.asctime_search) >= 0 RecursionError: maximum recursion depth exceeded while calling a Python object |
|||
msg360166 - (view) | Author: yang (fhsxfhsx) * | Date: 2020-01-17 10:09 | |
You assigned a handler to a variable `formatter`, and then called `setFormatter(formatter)`, but `formatter` is in fact a handler. The two classes `Formatter` and `Handler` happen to have a same name method `format` which is called when logging. So what happend is the logger wants to format your logging string, and it calls its handlers' `format` method. And in this handler's `format` method, the handler calls its formatter's `format` method, which ends to be another handler rather than a real formatter. And you repeated it 1000 times, which caused a 1000-level nested recursion. |
|||
msg360546 - (view) | Author: Vinay Sajip (vinay.sajip) * | Date: 2020-01-23 05:45 | |
@yang, thanks for the analysis - spot on. Closing, as this is a bug in the reporter's code and not in logging. |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:59:23 | admin | set | github: 83102 |
2020-01-23 05:45:48 | vinay.sajip | set | status: open -> closed resolution: rejected messages: + msg360546 stage: resolved |
2020-01-17 10:09:18 | fhsxfhsx | set | nosy:
+ fhsxfhsx messages: + msg360166 |
2020-01-14 20:44:22 | joy | set | files:
+ logging_test_script.py messages: + msg359992 |
2019-12-12 03:24:38 | joy | set | status: pending -> open messages: + msg358286 |
2019-12-06 07:25:25 | vinay.sajip | set | status: open -> pending messages: + msg357904 |
2019-11-26 19:29:00 | xtreak | set | nosy:
+ vinay.sajip, xtreak messages: + msg357526 |
2019-11-26 18:39:43 | joy | create |