classification
Title: SysLogHandler crash atexit
Type: Stage: needs patch
Components: Library (Lib), macOS Versions: Python 3.10, Python 3.9, Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: alanr, erlendaasland, jaraco, ned.deily, ronaldoussoren, vinay.sajip, youtux
Priority: normal Keywords: patch

Created on 2019-11-12 17:26 by jaraco, last changed 2021-01-06 18:23 by vinay.sajip.

Files
File name Uploaded Description Edit
0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch erlendaasland, 2020-02-28 22:08
0002-Improve-emit.patch erlendaasland, 2020-02-28 22:26 Improve emit()
Pull Requests
URL Status Linked Edit
PR 23661 closed jaraco, 2020-12-05 18:08
Messages (24)
msg356475 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 17:26
On Python 3.8.0:

$ python -c "import logging.handlers, socket; handler = logging.handlers.SysLogHandler(facility=logging.handlers.SysLogHandler.LOG_LOCAL7, address='/dev/log', socktype=socket.SOCK_RAW)"                                                     
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 2112, in shutdown
    h.close()
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/handlers.py", line 892, in close
    self.socket.close()
AttributeError: 'SysLogHandler' object has no attribute 'socket'

Probably that shouldn't happen.
msg356476 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 17:26
Same error on Python 2.7 and 3.7
msg356478 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 18:21
I only observe this issue on macOS. On Linux, the error doesn't occur.
msg356479 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 18:44
I guess that makes sense, as `/dev/log` doesn't exist on macOS. So maybe this usage is invalid. But still I'd expect the handler to error early or at least not error on shutdown.
msg356480 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 18:56
For background, this issue originated from https://github.com/pytest-dev/pytest-services/issues/20.
msg356481 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 19:18
The issue probably stems from https://github.com/python/cpython/blob/138ccbb02216ca086047c3139857fb44f3dab1f9/Lib/logging/handlers.py#L828-L835. I doubt the logic of that comment, as in the non-unix-socket case, the error is raised if a connection cannot be established. Fixing the issue by re-considering that comment would have backward-incompatible implications and would violate the intention of the comment's author.
msg356482 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 19:21
In the downstream issue, it's also reported that crashes occur in emit as well, suggesting that the comment is additionally wrong on that front.
msg356484 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2019-11-12 19:42
I could imagine extending the shutdown code to catch the reported error (https://github.com/python/cpython/blob/138ccbb02216ca086047c3139857fb44f3dab1f9/Lib/logging/__init__.py#L2130-L2135), but that wouldn't address the error in emit.

Similarly, the SysLogHandler could override shutdown to bypass the error if no socket attribute is present, but that again wouldn't address the emit case.
msg356490 - (view) Author: Ronald Oussoren (ronaldoussoren) * (Python committer) Date: 2019-11-12 21:46
As you noted /dev/log doesn't exist on macOS (the correct path is /var/run/syslog).

I guess the change that would be most in spirit of the comment is to set self.socket to None when the socket cannot be opened and test for that before closing the socket.  Likewise, emit() can test if self.socket is None and then attempt to open the socket (and not write to the log when the socket still is None)

This makes errors pass silently, but does match the spirit of the POSIX API (where the syslog function does not return an error).
msg359594 - (view) Author: Alan Robertson (alanr) Date: 2020-01-08 13:51
There are a variety of different reasons this can fail, not just on MacOS. You could give it a bad IP address of a server, etc. [That was my particular case].

The constructor should create an attribute 'socket' and initialize it to None early on. Then, the close function in logging/handlers.py should check for None. Or alternatively, it shouldn't register the object with atexit until it's been constructed "well-enough".
msg362920 - (view) Author: Erlend E. Aasland (erlendaasland) * (Python triager) Date: 2020-02-28 22:00
Attached patch is based on Ronald Oussoren's and Alan Robertson's comments: Initialise self.socket to None early in __init()__, and then check for None in close() and emit(). Passes make test on 3.9, 3.8 and 3.7.

If this solution is ok I'll add a unit test for the case that triggered this report and prepare a PR.
msg362926 - (view) Author: Erlend E. Aasland (erlendaasland) * (Python triager) Date: 2020-02-28 22:26
I'm a bit uncertain if the previous patch can handle the emit() case correctly. Proposed improvement in attached patch (0002-Improve-emit.patch).
msg382484 - (view) Author: Alessio Bogon (youtux) * Date: 2020-12-04 12:58
Is there any update on this issue? I'm experiencing the same problem on macos.
msg382576 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2020-12-05 17:49
I'll take a look at the patch and convert it to a PR.
msg382577 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2020-12-05 18:01
I've applied the patches and pushed them to https://github.com/jaraco/cpython/tree/bugfix/bpo-38780.

```
cpython master $ http https://bugs.python.org/file48933/0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch | git apply
cpython master $ git commit -a -m "bpo-38780: Initialize self.socket to None early in __init__() and check for None in close() and e
mit()" --author "Erlend E. Aasland <erlend.aasland@innova.no>" --date '28 Feb 2020 22:38:12 +0100'
[master e05b7d6c52] bpo-38780: Initialize self.socket to None early in __init__() and check for None in close() and emit()
 Author: Erlend E. Aasland <erlend.aasland@innova.no>
 Date: Fri Feb 28 22:38:12 2020 +0100
 1 file changed, 7 insertions(+), 2 deletions(-)
cpython master $ http https://bugs.python.org/file48934/0002-Improve-emit.patch | git apply
cpython master $ git commit -a -m "bpo-38780: Address uncertainty in handling of emit() case." --author "Erlend E. Aasland <erlend.a
asland@innova.no>" --date '28 Feb 2020 23:22:58 +0100'
[master 045b6381b5] bpo-38780: Address uncertainty in handling of emit() case.
 Author: Erlend E. Aasland <erlend.aasland@innova.no>
 Date: Fri Feb 28 23:22:58 2020 +0100
 1 file changed, 7 insertions(+), 5 deletions(-)
cpython master $ git checkout -b bugfix/bpo-38780
Switched to a new branch 'bugfix/bpo-38780'
cpython bugfix/bpo-38780 $ gpj
To https://github.com/jaraco/cpython
 * [new branch]            bugfix/bpo-38780 -> bugfix/bpo-38780
 * [new tag]               v3.10.0a2 -> v3.10.0a2
Branch 'bugfix/bpo-38780' set up to track remote branch 'bugfix/bpo-38780' from 'jaraco'.
```
msg382579 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2020-12-05 18:29
Erlend, inspired by your patches, I created https://github.com/python/cpython/pull/23661/commits/e9723003d49c722d57a69e5016b442d4d752fc6d, which uses a NullSocket instance instead of None, allowing the behavior-suppression to be encapsulated in a single place and swapped out by creation of a proper socket instance.

I do believe this approach addresses the issue. Are you still willing to put together a test case or more?
msg382607 - (view) Author: Erlend E. Aasland (erlendaasland) * (Python triager) Date: 2020-12-06 21:05
Thanks, Jason! I won't have time to look at this until perhaps next week, however, feel free to add tests as you like.

N.B.: My patches might not be the best solution to the problem; it was just something I threw up based on my initial understanding of the problem.
msg384128 - (view) Author: Jason R. Coombs (jaraco) * (Python committer) Date: 2020-12-31 18:57
I started work on a test in https://github.com/jaraco/cpython/tree/bugfix/bpo-38780-test, but (a) the test was failing to exhibit the expected failures, and (b) I realized that the fix isn't having the intended effect either, because for unix sockets, [self.socket is unconditionally set](https://github.com/python/cpython/blob/dfdca85dfa64e72df385b3a486f85b773fc0f135/Lib/logging/handlers.py#L872), overriding any NullSocket or None value.

The SysLogHandler code will need to be reorganized if self.socket is intended to model two modes (broken and initialized).

I'm not sure when I'll get another chance to take a look at this, but I'll not be able to wrap it up today, so I'm going to unassign it for now.
msg384139 - (view) Author: Erlend E. Aasland (erlendaasland) * (Python triager) Date: 2020-12-31 20:44
I've forked your work, Jason:
https://github.com/erlend-aasland/cpython/tree/bpo-38780-test

I added the test from msg356475, and I'm able to reproduce it by asserting that the `socket` attribute is present (commit f0f8ff8f06afd43947e268824aa4381add05ce8f)
msg384140 - (view) Author: Erlend E. Aasland (erlendaasland) * (Python triager) Date: 2020-12-31 20:51
Using a NullSocket fixes the test in commit f0f8ff8f06afd43947e268824aa4381add05ce8f
msg384518 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-01-06 17:30
TBH as I said in the now-closed PR, using a NullSocket seems overkill. As mentioned in msg359594, it seems to make more sense to assign a socket attribute to None early in the constructor. If an error occurs during socket creation, the socket attribute will remain at None. When closing, just ensure the socket attribute isn't None before trying to close it. This mirrors what SocketHandler does.
msg384520 - (view) Author: Alan Robertson (alanr) Date: 2021-01-06 17:32
On Wed, Jan 6, 2021, at 10:30 AM, Vinay Sajip wrote:
> 
> Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:
> 
> TBH as I said in the now-closed PR, using a NullSocket seems overkill. 
> As mentioned in msg359594, it seems to make more sense to assign a 
> socket attribute to None early in the constructor. If an error occurs 
> during socket creation, the socket attribute will remain at None. When 
> closing, just ensure the socket attribute isn't None before trying to 
> close it. This mirrors what SocketHandler does.
> 
> ----------
> 
> _______________________________________
> Python tracker <report@bugs.python.org>
> <https://bugs.python.org/issue38780>
> _______________________________________
>

-- 
  Alan Robertson
  alanr@unix.sh
msg384521 - (view) Author: Alan Robertson (alanr) Date: 2021-01-06 17:34
As far as I know, this only happens during shutdown. During shutdown it has already removed the attribute as part of the teardown process. In this case adding the attribute at the begining will do no good.

On Wed, Jan 6, 2021, at 10:30 AM, Vinay Sajip wrote:
> 
> Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:
> 
> TBH as I said in the now-closed PR, using a NullSocket seems overkill. 
> As mentioned in msg359594, it seems to make more sense to assign a 
> socket attribute to None early in the constructor. If an error occurs 
> during socket creation, the socket attribute will remain at None. When 
> closing, just ensure the socket attribute isn't None before trying to 
> close it. This mirrors what SocketHandler does.
> 
> ----------
> 
> _______________________________________
> Python tracker <report@bugs.python.org>
> <https://bugs.python.org/issue38780>
> _______________________________________
>
msg384529 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-01-06 18:23
> As far as I know, this only happens during shutdown. During shutdown it has already removed the attribute as part of the teardown process. In this case adding the attribute at the begining will do no good.

Certainly, that's true - there are a number of issues that get laid at logging's door because of interpreter shutdown sometimes intersecting with asyncio, threads and error handling using logging to report, which then fails in turn because of inconsistent interpreter state during shutdown. That would then perhaps be a "wontfix" or "cantfix" because there is no good solution. But the missing socket attribute in SysLogHandler might cause other problems in the future - I'm just saying that the approach you suggested is, to me, preferable to the NullSocket approach to deal with a similar issue in this area.
History
Date User Action Args
2021-01-06 18:23:31vinay.sajipsetmessages: + msg384529
2021-01-06 17:34:18alanrsetmessages: + msg384521
2021-01-06 17:32:44alanrsetmessages: + msg384520
2021-01-06 17:30:15vinay.sajipsetmessages: + msg384518
2020-12-31 20:51:23erlendaaslandsetmessages: + msg384140
2020-12-31 20:44:32erlendaaslandsetmessages: + msg384139
2020-12-31 18:57:44jaracosetstage: patch review -> needs patch
2020-12-31 18:57:31jaracosetassignee: jaraco ->
2020-12-31 18:57:21jaracosetmessages: + msg384128
2020-12-06 21:05:44erlendaaslandsetmessages: + msg382607
2020-12-05 18:29:14jaracosetmessages: + msg382579
2020-12-05 18:10:06jaracosetversions: + Python 3.10, - Python 2.7, Python 3.7
2020-12-05 18:08:26jaracosetstage: patch review
pull_requests: + pull_request22527
2020-12-05 18:01:26jaracosetmessages: + msg382577
2020-12-05 17:49:50jaracosetassignee: jaraco
messages: + msg382576
2020-12-04 12:58:50youtuxsetmessages: + msg382484
2020-12-03 13:16:11youtuxsetnosy: + youtux
2020-02-28 22:26:21erlendaaslandsetfiles: + 0002-Improve-emit.patch

messages: + msg362926
2020-02-28 22:08:42erlendaaslandsetfiles: + 0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch
2020-02-28 22:08:32erlendaaslandsetfiles: - 0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch
2020-02-28 22:00:50erlendaaslandsetfiles: + 0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch

nosy: + erlendaasland
messages: + msg362920

keywords: + patch
2020-01-08 13:51:35alanrsetnosy: + alanr
messages: + msg359594
2019-11-12 21:46:50ronaldoussorensetmessages: + msg356490
2019-11-12 19:42:04jaracosetmessages: + msg356484
2019-11-12 19:21:30jaracosetmessages: + msg356482
2019-11-12 19:18:52jaracosetmessages: + msg356481
2019-11-12 18:56:17jaracosetmessages: + msg356480
2019-11-12 18:44:16jaracosetmessages: + msg356479
2019-11-12 18:39:32ned.deilysetnosy: + vinay.sajip
2019-11-12 18:21:21jaracosetnosy: + ronaldoussoren, ned.deily
components: + Library (Lib), macOS
2019-11-12 18:21:01jaracosetmessages: + msg356478
2019-11-12 17:26:38jaracosetmessages: + msg356476
versions: + Python 2.7, Python 3.7, Python 3.8, Python 3.9
2019-11-12 17:26:09jaracocreate