SysLogHandler crash atexit

[jaraco]

BPO	38780
Nosy	@vsajip, @ronaldoussoren, @jaraco, @ned-deily, @youtux, @erlend-aasland, @Alan-R
PRs	bpo-38780: Avoid errors in SyslogHandler when socket is not set up. #23661
Files	0001-bpo-38780-Harden-socket-use-in-logging.handlers.patch 0002-Improve-emit.patch: Improve emit()

^{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 = None
created_at = <Date 2019-11-12.17:26:08.989>
labels = ['OS-mac', '3.8', 'library', '3.9', '3.10']
title = 'SysLogHandler crash atexit'
updated_at = <Date 2021-01-06.18:23:31.151>
user = 'https://github.com/jaraco'

bugs.python.org fields:

activity = <Date 2021-01-06.18:23:31.151>
actor = 'vinay.sajip'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)', 'macOS']
creation = <Date 2019-11-12.17:26:08.989>
creator = 'jaraco'
dependencies = []
files = ['48933', '48934']
hgrepos = []
issue_num = 38780
keywords = ['patch']
message_count = 24.0
messages = ['356475', '356476', '356478', '356479', '356480', '356481', '356482', '356484', '356490', '359594', '362920', '362926', '382484', '382576', '382577', '382579', '382607', '384128', '384139', '384140', '384518', '384520', '384521', '384529']
nosy_count = 7.0
nosy_names = ['vinay.sajip', 'ronaldoussoren', 'jaraco', 'ned.deily', 'youtux', 'erlendaasland', 'alanr']
pr_nums = ['23661']
priority = 'normal'
resolution = None
stage = 'needs patch'
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue38780'
versions = ['Python 3.8', 'Python 3.9', 'Python 3.10']

[jaraco]

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.

[jaraco]

Same error on Python 2.7 and 3.7

[jaraco]

I only observe this issue on macOS. On Linux, the error doesn't occur.

[jaraco]

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.

[jaraco]

For background, this issue originated from pytest-dev/pytest-services#20.

[jaraco]

The issue probably stems from

cpython/Lib/logging/handlers.py

Lines 828 to 835 in 138ccbb

	# Syslog server may be unavailable during handler initialisation.
	# C's openlog() function also ignores connection errors.
	# Moreover, we ignore these errors while logging, so it not worse
	# to ignore it also here.
	try:
	self._connect_unixsocket(address)
	except OSError:
	pass

. 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.

[jaraco]

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.

[jaraco]

I could imagine extending the shutdown code to catch the reported error (

cpython/Lib/logging/__init__.py

Lines 2130 to 2135 in 138ccbb

	except (OSError, ValueError):
	# Ignore errors which might be caused
	# because handlers have been closed but
	# references to them are still around at
	# application exit.
	pass

), 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.

[ronaldoussoren]

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).

[Alan-R]

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".

[erlend-aasland]

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.

[erlend-aasland]

I'm a bit uncertain if the previous patch can handle the emit() case correctly. Proposed improvement in attached patch (0002-Improve-emit.patch).

[youtux]

Is there any update on this issue? I'm experiencing the same problem on macos.

[jaraco]

I'll take a look at the patch and convert it to a PR.

[jaraco]

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'.

[jaraco]

Erlend, inspired by your patches, I created e972300, 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?

[erlend-aasland]

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.

[jaraco]

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, 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.

[erlend-aasland]

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 f0f8ff8)

[erlend-aasland]

Using a NullSocket fixes the test in commit f0f8ff8

[vsajip]

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.

[Alan-R]

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

[Alan-R]

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\>

---

[vsajip]

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.

[vsajip]

I think this issue is out of date due to more recent changes. Certainly, I can't reproduce the original report in the main, 3.11 or 3.10 branches.