RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1420505 - Using "systemd.log_level=debug systemd.log_target=kmsg" causes systemd to send "Executing: ..." message to remote clients.
Summary: Using "systemd.log_level=debug systemd.log_target=kmsg" causes systemd to sen...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd
Version: 7.3
Hardware: All
OS: Linux
unspecified
high
Target Milestone: rc
: ---
Assignee: Jan Synacek
QA Contact: Frantisek Sumsal
URL:
Whiteboard:
Depends On:
Blocks: 1298243 1420515 1420851 1466365
TreeView+ depends on / blocked
 
Reported: 2017-02-08 20:37 UTC by Bryan Mason
Modified: 2023-09-15 00:01 UTC (History)
8 users (show)

Fixed In Version: systemd-219-44.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1420515 (view as bug list)
Environment:
Last Closed: 2018-04-10 11:19:30 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 2895521 0 None None None 2017-02-20 20:25:57 UTC
Red Hat Product Errata RHBA-2018:0711 0 None None None 2018-04-10 11:20:54 UTC

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


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