Bug 444084

Summary: ksreen should not output information as warning
Product: [Plasma] KScreen Reporter: pat_h
Component: libkscreenAssignee: kscreen-bugs-null <kscreen-bugs-null>
Status: RESOLVED FIXED    
Severity: minor CC: nate, pat_h
Priority: NOR    
Version First Reported In: 5.23.0   
Target Milestone: ---   
Platform: Debian unstable   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:

Description pat_h 2021-10-20 04:57:40 UTC
SUMMARY
Probably due to the use of systemd, kscreen outputs a lot of quite trivial output as a warning and therefore possibly masking real problems. In my journal more than 75% of all warnings come from kscreen.

STEPS TO REPRODUCE
1. Login
2. journalctl --boot --priority warning

OBSERVED RESULT
The output is full of kscreen.xcb.helper and kscreen.xrandr information messages with priority warning.

EXPECTED RESULT
The messages should have at maximum priority notice and probably only priority info.

SOFTWARE/OS VERSIONS
Operating System: Debian GNU/Linux
KDE Plasma Version: 5.23.0
KDE Frameworks Version: 5.86.0
Qt Version: 5.15.2
Kernel Version: 5.14.0-2-amd64 (64-bit)
Graphics Platform: X11
Processors: 4 × Intel® Core™ i5-6500 CPU @ 3.20GHz
Memory: 11,6 GiB of RAM
Graphics Processor: Mesa Intel® HD Graphics 530

ADDITIONAL INFORMATION
I am not sure, whether this is explicit logging on KScreen side with priority warning or just having its output logged from systemd with an implicit default warn level.
Comment 1 pat_h 2021-10-21 03:45:45 UTC
Some additional observations:

The output is defined in libkscreen, not in kscreen itself. Therefore, I changed relevant component.

Inside kscreen, the output is, e.g., defined in backends/xrandr/xrandrconfig.cpp or backends/xcbeventlistener.cpp.

There, qCDebug is used as output function, which seems to be correct on first look, because especially qCWarning is not used (as for other warnings in the file which are not triggered).

The journal does not get the messages via the regular logging mechanisms, but really via stdout, which can be shown by using "journalctl --priority warning --boot -o verbose". A shortened output looks like this:
Wed 2021-10-20 06:43:05.567398 CEST
    _TRANSPORT=stdout
    _UID=1000
    _GID=1000
    _SYSTEMD_OWNER_UID=1000
    _SYSTEMD_UNIT=user@1000.service
    _SYSTEMD_SLICE=user-1000.slice
    PRIORITY=4
    _SYSTEMD_CGROUP=/user.slice/user-1000.slice/user@1000.service/app.slice/dbus.service
    _SYSTEMD_USER_UNIT=dbus.service
    _SYSTEMD_USER_SLICE=app.slice
    SYSLOG_IDENTIFIER=org.kde.KScreen
    _COMM=kscreen_backend
    _EXE=/usr/lib/x86_64-linux-gnu/libexec/kf5/kscreen_backend_launcher
    _CMDLINE=/usr/lib/x86_64-linux-gnu/libexec/kf5/kscreen_backend_launcher
    MESSAGE=kscreen.xcb.helper: RRNotify_CrtcChange
    _PID=1325
Comment 2 pat_h 2021-10-21 06:02:04 UTC
Some more observations:

qCDebug really goes to stderr according to https://stackoverflow.com/a/26325743
"If the process' stderr has a console attached, that's where the debug log will go."

So one idea could be, to remove stdout (due to the entry in the journal) and stderr (due to the quote above) from kscreen via systemd. Unfortunetly, there is no kscreen service unit. This is the shortened "systemd --user show" hierarchy:
   CGroup: /user.slice/user-1000.slice/user@1000.service
           ├─app.slice
           │ ├─dbus.service
           │ │ └─1273 /usr/lib/x86_64-linux-gnu/libexec/kf5/kscreen_backend_launcher

So kscreen_backend-launcher is executed by dbus.service. However, changing stdout and stderr of dbus.service via "systemctl --user edit dbus.service" and adding
[Service]
StandardOutput=null
StandardError=null
although changing (after a restart) the configuration for dbus.service shown by "systemctl --user show dbus.service" to
StandardOutput=null
StandardError=null
does not change the logging behavior.

I assume this is, as kscreen_backend_launcher is probably started via dbus and therefore probably does not inherent stdout and stderr settings. This is confirmed by "ls -l /proc/$(pgrep kscreen)/fd"
lrwx------ 1 pat pat 64 21. Okt 07:26 0 -> /dev/null
lrwx------ 1 pat pat 64 21. Okt 07:26 1 -> 'socket:[17265]'
lrwx------ 1 pat pat 64 21. Okt 07:26 2 -> 'socket:[17266]'
So stdout and stderr do not go to /dev/null.

This is what "lsof | rg 1726[56]" (rg is grep-like ripgrep) outputs:
kscreen_b 1273                             pat    1u     unix 0x00000000a3854333        0t0      17265 type=STREAM
kscreen_b 1273                             pat    2u     unix 0x00000000e0deba49        0t0      17266 type=STREAM
kscreen_b 1273 1278 QXcbEvent              pat    1u     unix 0x00000000a3854333        0t0      17265 type=STREAM
kscreen_b 1273 1278 QXcbEvent              pat    2u     unix 0x00000000e0deba49        0t0      17266 type=STREAM
kscreen_b 1273 1280 QDBusConn              pat    1u     unix 0x00000000a3854333        0t0      17265 type=STREAM
kscreen_b 1273 1280 QDBusConn              pat    2u     unix 0x00000000e0deba49        0t0      17266 type=STREAM
1273 is kscreen_backend_launcher (from "pgrep kscreen").

This is, what "ss | rg 1726[56]" outputs:
u_str ESTAB      0      0                             /run/systemd/journal/stdout 18202                  * 17265        
u_str ESTAB      0      0                                                       * 17265                  * 18202        
u_str ESTAB      0      0                             /run/systemd/journal/stdout 18203                  * 17266        
u_str ESTAB      0      0                                                       * 17266                  * 18203

According to "man systemd-journald" /run/systemd/journal/stdout is a "Socket[...] that systemd-journald will listen on and [is] visible in the file system".

The question is, how to avoid this socket connection with systemd's stdout logging to the Journal and instead use the advanced normal logging mechanism? Or, maybe as a temporary workaround, at least reduce the priority of systemd's stdout logging.
Comment 3 pat_h 2021-10-22 04:26:25 UTC
The assumption, that kscreen_backend_launcher is D-Bus activated is correct. The D-Bus service file is located in /usr/share/dbus-1/services/org.kde.kscreen.service and has the following content:
[D-BUS Service]
Name=org.kde.KScreen
Exec=/usr/lib/x86_64-linux-gnu/libexec/kf5/kscreen_backend_launcher

Now the question arises how to change stdout or stderr in a D-Bus service file. It seems to be possible to append some arguments to the Exec line (as in org.freedesktop.Telepathy.Client.KTp.Approver.service), but otherwise the only used attributes seem to be (found by cat /usr/share/dbus-1/services/*.service | rg = | cut -f1 -d= | sort | uniq):
AssumedAppArmorLabel, Exec, Name, SystemdService, User

There seems to be some documentation in https://dbus.freedesktop.org/doc/dbus-daemon.1.html in chapter INTEGRATING SYSTEM SERVICES. Maybe it's possible to not start kscreen_backend_launcher from the D-Bus service file, but instead start a systemd service, which then starts kscreen_backend_launcher with the correct logging options.
Comment 4 pat_h 2021-10-23 04:11:02 UTC
Going with the systemd unit file is the way to go.

After appending

SystemdService=plasma-kscreen.service

to /usr/share/dbus-1/services/org.kde.kscreen.service

and creating /usr/lib/systemd/user/plasma-kscreen.service with the content

[Unit]
Description=KScreen
PartOf=graphical-session.target

[Service]
ExecStart=/usr/lib/x86_64-linux-gnu/libexec/kf5/kscreen_backend_launcher
Type=dbus
BusName=org.kde.KScreen
TimeoutSec=5sec
Slice=background.slice
# Disable restart as we're dbus activated anyway
Restart=no

and doing a restart, there are nor further kscreen warnings in the Journal. Instead they are logged with priority info as they should be, which can be checked with "journalctl --boot --output verbose _SYSTEMD_USER_UNIT=plasma-kscreen.service".

I used plasma-krunner.service as a template for the plasma-kscreen.service above, which means, that the kscreen backend moves from the app.slice into the background.slice. I think this makes sense, as the kscreen backend is not really an app, but I wanted to highlight this, as it is, strictly speaking, a separate issue.

So the only remaining piece for me, is to create a patch from the instruction above and submit it, I guess.
Comment 5 Bug Janitor Service 2021-11-05 04:14:22 UTC
A possibly relevant merge request was started @ https://invent.kde.org/plasma/libkscreen/-/merge_requests/38
Comment 6 David Redondo 2021-11-15 10:46:33 UTC
Git commit e755e97c58589275436d880ded96a160f5ba3c79 by David Redondo, on behalf of Patrick Häcker.
Committed on 15/11/2021 at 08:26.
Pushed by davidedmundson into branch 'master'.

Fix using correct log level by using systemd unit

When kscreen_backend is started by D-Bus activation, the Journal does
not use the correct log levels, but instead all logs are output at
priority warning.

Therefore, do the D-Bus activation with a systemd unit file, so that
log levels keep their intended priority.

This has the additional benefit of moving kscreen_backend from app.slice
to background.slice.

M  +7    -0    src/backendlauncher/CMakeLists.txt
M  +1    -0    src/backendlauncher/org.kde.kscreen.service.cmake
A  +12   -0    src/backendlauncher/plasma-kscreen.service.cmake

https://invent.kde.org/plasma/libkscreen/commit/e755e97c58589275436d880ded96a160f5ba3c79