Red Hat Bugzilla – Bug 1420505
Using "systemd.log_level=debug systemd.log_target=kmsg" causes systemd to send "Executing: ..." message to remote clients.
Last modified: 2018-04-10 07:20:54 EDT
Description of problem: 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. Version-Release number of selected component (if applicable): systemd-219-30.el7_3.6 How reproducible: 100% Steps to Reproduce: 1. Set LogLevel=debug and LogTarget=kmsg, either through system.conf file or the kernel command-line (as described in https://freedesktop.org/wiki/Software/systemd/Debugging/) 2. Enable a socket-based service, like cups-lpd. 3. Use telnet to connect to the socket based service. Actual results: # telnet 127.0.0.1 515 Trying 127.0.0.1... Connected to 127.0.0.1. Escape character is '^]'. Executing: /usr/lib/cups/daemon/cups-lpd Expected results: The "Executing: /usr/lib/cups/daemon/cups-lpd" message should not be displayed. Additional info: This is causing a real-world problem with remote LPD clients connecting to RHEL. The "Executing..." message violates the LPD protocol as described in RFC 1179.
This issue occurs because exec_child() sets its UID to the User specified in the unit file. With LogTarget=kmsg set . . . if (_unlikely_(log_get_max_level() >= LOG_DEBUG)) { _cleanup_free_ char *line; line = exec_command_line(final_argv); if (line) { log_open(); . . . the call to log_open() ends up calling log_open_kmsg() which fails because the user "lp" doesn't have the privilege to open /dev/kmsg. As a result, log_open_console() is called, and because are not PID 1, console_fd is set to STDERR_FILENO, which is the socket_fd. log_unit_struct(params->unit_id, LOG_DEBUG, "EXECUTABLE=%s", command->path, LOG_MESSAGE("Executing: %s", line), NULL); As a result, log_unit_struct() ends up sending the message to the socket_fd, which is connected to our remote client, which isn't expecting this. static int log_open_console(void) { if (console_fd >= 0) return 0; if (getpid() == 1) { console_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC); if (console_fd < 0) return console_fd; } else console_fd = STDERR_FILENO; return 0; } static int log_open_kmsg(void) { if (kmsg_fd >= 0) return 0; kmsg_fd = open("/dev/kmsg", O_WRONLY|O_NOCTTY|O_CLOEXEC); if (kmsg_fd < 0) return -errno; return 0; } int log_open(void) { if ((log_target != LOG_TARGET_AUTO && log_target != LOG_TARGET_SAFE) || getpid() == 1 || isatty(STDERR_FILENO) <= 0) { if (log_target == LOG_TARGET_AUTO || log_target == LOG_TARGET_SAFE || log_target == LOG_TARGET_JOURNAL_OR_KMSG || log_target == LOG_TARGET_SYSLOG_OR_KMSG || log_target == LOG_TARGET_KMSG) { r = log_open_kmsg(); if (r >= 0) { log_close_journal(); log_close_syslog(); log_close_console(); return r; } } } log_close_journal(); log_close_syslog(); return log_open_console(); }
Could we do this in log_open_console() to avoid this: static int log_open_console(void) { if (console_fd >= 0) return 0; if (getpid() == 1) { console_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC); if (console_fd < 0) return console_fd; } else { struct stderr_stat; fstat(STDERR_FILENO, &stderr_stat); if ( (stderr_stat.st_mode & S_IFMT) == S_IFSOCK ) return -1; // or some appropriate error code else console_fd = STDERR_FILENO; } return 0; }
Adding StandardError=journal to /usr/lib/systemd/system/cups-lpd.socket also works around the problem. Although if the journal isn't running, the message will got to the socket as before.
(In reply to Bryan Mason from comment #3) > Adding > > StandardError=journal > > to /usr/lib/systemd/system/cups-lpd.socket also works around the problem. > Although if the journal isn't running, the message will got to the socket as > before. The file being modified is, of course /usr/lib/systemd/system/cups-lpd@.service, not cups-lpd.socket.
This has been fixed in systemd release 233. A backport may be appropriate.
(In reply to Suraj Jitindar Singh from comment #5) > This has been fixed in systemd release 233. A backport may be appropriate. Where?
Upstream: www.freedesktop.org/wiki/Software/systemd
Well, no. Since you wrote that this has been fixed, you should back it up with a link to the patch or pull request in which it was fixed. That's what I meant by "Where?", sorry, I should have made it clear.
Whoops. I never linked this to the upstream issue I opened: https://github.com/systemd/systemd/issues/5401
And here's the commit that closed that issue: https://github.com/systemd/systemd/commit/48a601f
https://github.com/lnykryn/systemd-rhel/pull/132
fix merged to upstream staging branch -> https://github.com/lnykryn/systemd-rhel/pull/132 -> post
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2018:0711