Using "systemd.log_level=debug systemd.log_target=kmsg" causes systemd to send "Executing: ..." message to remote clients

[bmasonrh]

Submission type

• Bug report
• Request for enhancement (RFE)

systemd version the issue has been seen with

systemd-219-30.el7_3.6 in RHEL 7
systemd-229-18.fc24.x86_64

Used distribution

RHEL 7
Fedora 24

In case of bug report: Unexpected behaviour you saw

When LogLevel=debug and LogTarget=kmsg, systemd will send the message
"Executing: /path/to/exececutable" to the socket that is connected
to the remote client in a socket-based activation unit. This can
cause problems with some remote clients. For example, the message
message "Executing /usr/lib/cups/daemon/cups-lpd" is being sent to
remote LPD clients. This is causing the remote clients to abort the
connection because this message violates the LPD protocol as defined
in RFC 1179.

In case of bug report: Steps to reproduce the problem

Install, enable, and start cups-lpd:

# dnf install cups-lpd
# systemctl enable cups-lpd.socket
# systemctl start cups-lpd.socket

Run telnet to connect to the LPD port (515):

# telnet 127.0.0.1 515
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
cups-lpd@2-127.0.0.1:515-127.0.0.1:59694.service: Executing: /usr/lib/cups/daemon/cups-lpd

The last message "... Executing: /usr/lib/cups/daemon/cups-lpd" should not appear.

[bmasonrh]

This problem occurs when User=<something> is set in the service file. systemd changes to that user before running this:

        if (_unlikely_(log_get_max_level() >= LOG_DEBUG)) {
               _cleanup_free_ char *line;
 
                line = exec_command_line(final_argv);
                if (line) {
                        log_open();
                        log_unit_struct(params->unit_id,
                                        LOG_DEBUG,
                                        "EXECUTABLE=%s", command->path,
                                        LOG_MESSAGE("Executing: %s", line),
                                        NULL);

With LogLevel=debug and LogTarget=kmsg, the call to log_open() attempts to call log_open_kmsg() but that fails because the non-root user isn't able to open /dev/ksmg. log_open() resorts to calling log_open_console() which sets console_fd to STDERR_FILENO because we're not PID 1 (systemd has forked() by this point). The end result is that log_unit_struct() ends up dumping the "Executing %s" message to stderr, which has been connected to the socket communicating with the remote client. The remote client gets the unexpected message and aborts.

[poettering]

Fix waiting in #5411.