Bug 1420505

Summary: Using "systemd.log_level=debug systemd.log_target=kmsg" causes systemd to send "Executing: ..." message to remote clients.
Product: Red Hat Enterprise Linux 7 Reporter: Bryan Mason <bmason>
Component: systemdAssignee: Jan Synacek <jsynacek>
Status: CLOSED ERRATA QA Contact: Frantisek Sumsal <fsumsal>
Severity: high Docs Contact:
Priority: unspecified    
Version: 7.3CC: fsumsal, james.hofmeister, jsynacek, ktordeur, kwalker, michael.chisholm, sursingh, systemd-maint-list
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: systemd-219-44.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1420515 (view as bug list) Environment:
Last Closed: 2018-04-10 11:19:30 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1298243, 1420515, 1420851, 1466365    

Description Bryan Mason 2017-02-08 20:37:00 UTC
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.

Comment 1 Bryan Mason 2017-02-16 23:36:58 UTC
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();
}

Comment 2 Bryan Mason 2017-02-16 23:49:32 UTC
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;
}

Comment 3 Bryan Mason 2017-02-20 18:50:33 UTC
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.

Comment 4 Bryan Mason 2017-02-20 20:10:40 UTC
(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.

Comment 5 Suraj Jitindar Singh 2017-05-25 00:58:37 UTC
This has been fixed in systemd release 233. A backport may be appropriate.

Comment 6 Jan Synacek 2017-05-25 08:26:28 UTC
(In reply to Suraj Jitindar Singh from comment #5)
> This has been fixed in systemd release 233. A backport may be appropriate.

Where?

Comment 7 Suraj Jitindar Singh 2017-05-26 06:02:02 UTC
Upstream: www.freedesktop.org/wiki/Software/systemd

Comment 8 Jan Synacek 2017-05-29 05:18:09 UTC
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.

Comment 11 Bryan Mason 2017-08-17 17:30:00 UTC
Whoops.  I never linked this to the upstream issue I opened:

https://github.com/systemd/systemd/issues/5401

Comment 12 Bryan Mason 2017-08-17 17:31:50 UTC
And here's the commit that closed that issue:

https://github.com/systemd/systemd/commit/48a601f

Comment 13 Jan Synacek 2017-08-18 08:47:42 UTC
https://github.com/lnykryn/systemd-rhel/pull/132

Comment 15 Lukáš Nykrýn 2017-09-07 13:52:56 UTC
fix merged to upstream staging branch -> https://github.com/lnykryn/systemd-rhel/pull/132 -> post

Comment 21 errata-xmlrpc 2018-04-10 11:19:30 UTC
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

Comment 22 Red Hat Bugzilla 2023-09-15 00:01:14 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 500 days