Bug 7878 - Our systemd services close stderr too early when service is stopped
Summary: Our systemd services close stderr too early when service is stopped
Status: CLOSED FIXED
Alias: None
Product: ThinLinc
Classification: Unclassified
Component: Other (show other bugs)
Version: trunk
Hardware: PC Unknown
: P2 Normal
Target Milestone: 4.15.0
Assignee: Linn
URL:
Keywords: prosaic, wilsj_tester
Depends on:
Blocks:
 
Reported: 2022-04-01 17:25 CEST by Linn
Modified: 2022-04-07 11:00 CEST (History)
1 user (show)

See Also:
Acceptance Criteria:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Description Linn cendio 2022-04-01 17:25:58 CEST 
Our daemon services customises stderr to be able to get the kind of line buffering we want. 

This issue is only seen on Python 3.6 and below, where we have to replace the stderr object to configure it. On Python 3.7+, reconfigure() can be called on the existing stderr object, which means that stderr can be edited without creating a new object for it.

When replacing the stderr object in Python <= 3.6, we get a resource warning about stderr not being properly closed, see a minimal code example below. However, note that we only get this warning when running it with the python3-wrapper provided by ThinLinc.

> import sys
> 
> sys.stdout.flush()
> sys.stdout = open(sys.stdout.fileno(), "w", errors="replace")

> [cendio@lab-209 ~]$ /opt/thinlinc/libexec/python3 ./<file>
> sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name=1 mode='w' encoding='UTF-8'>

After this resource warning is printed, the file is closed. [1] 

This is also how we handle stderr in our service, which means that stderr for our services might be closed prematurely when stopping them, since we effectively disable any printing to stderr after the close. 

There are no resource warnings to be found in the logs after stopping a service. However, this might due to this bug itself since the resource warning is printed on stderr.


[1]: https://github.com/python/cpython/blob/v3.6.8/Lib/_pyio.py#L1516
Comment 1 Linn cendio 2022-04-04 09:17:08 CEST 
(In reply to Linn from comment #0)
> ..., see a minimal code example below.
The code example uses stdout, but stderr has the same behaviour.
Comment 2 Linn cendio 2022-04-04 11:09:44 CEST 
(In reply to Linn from comment #0)
> ... our services might be closed prematurely when stopping them, since we
> effectively disable any printing to stderr after the close. 
> 
> There are no resource warnings to be found in the logs after stopping a
> service. However, this might due to this bug itself since the resource
> warning is printed on stderr.

Using strace on tlwebadm we can verify that this bug happens in reality and also that the resource warning would have been printed if not for this bug:
> [cendio@lab-209 ~]$ strace -p <pid>'
> [cendio@lab-209 ~]$ sudo systemctl stop tlwebadm
> ...
> close(2)                                = 0
> munmap(0x7f0151864000, 262144)          = 0
> munmap(0x7f01518a4000, 262144)          = 0
> write(2, "sys:1: ResourceWarning: unclosed"..., 91) = -1 EBADF (Bad file descriptor)
> write(2, "sys:1: ResourceWarning: unclosed"..., 91) = -1 EBADF (Bad file descriptor)
Comment 4 Linn cendio 2022-04-04 14:23:37 CEST 
Tested on RHEL 8 and following the steps in comment 2 no longer shows a close on stderr (file descriptor 2).
Comment 5 William Sjöblom cendio 2022-04-07 11:00:49 CEST 
I have reproduced the issue with the 1.14.0 server and tested the fix
with server build #2558. Testing was carried out on SLES12 running
Python 3.4.

Neither stderr nor stdout is now closed when `systemctl stop':ing any
of our daemons (i.e. we now get the same behavior as if we wouldn't have
overwritten stderr). Since this bug is pretty hypothetical in nature,
this is good enough for me.

Marking as closed.
Note You need to log in before you can comment on or make changes to this bug.