syslogd: Terminate pipe processes gracefully

[jfree]

Summary

Pipe actions spawn processes based on the command provided in the
syslogd configuration file. When a HUP signal is received, enter
these processes into the deadq instead of immediately killing them.
This matches the behavior of syslogd prior to it being Capsicumized.

Fixes: d2d180fb7736

Test Plan

Using test provided by bug report:
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=291557

$ logger -p local2.warning -t logger message1
$ killall -1 syslogd
$ logger -p local2.warning -t logger message2
$ killall -1 syslogd

$ tail /var/log/messages
Dec 22 06:44:54 CURRENT logger[6027]: message1
Dec 22 06:44:55 CURRENT pipe-test[6032]: 6028 START
Dec 22 06:44:55 CURRENT pipe-test[6036]: 6028 Dec 22 06:44:54 CURRENT logger[6027]: message1
Dec 22 06:44:56 CURRENT pipe-test[6041]: 6028 END
Dec 22 06:44:59 CURRENT logger[6045]: message2
Dec 22 06:44:59 CURRENT pipe-test[6050]: 6046 START
Dec 22 06:44:59 CURRENT pipe-test[6054]: 6046 Dec 22 06:44:59 CURRENT logger[6045]: message2
Dec 22 06:45:02 CURRENT pipe-test[6061]: 6046 END

[markj]

Is it possible to convert the test scenario into a regression test case?

[jfree]

Tests added. I forgot to add the review link into the commit message... oops. Closing this.

[fbsd_opal.com]

There may be a problem with this new code at lines 380..382 on the right:

} else if (f->f_type == F_PIPE && f->f_procdesc != -1) {
        f->f_dq = deadq_enter(f->f_procdesc);
}

I am seeing the following:

• my syslogd here has a permanently-running sub-process started with "| exec /path/to/foo"
• at some point in time, syslogd does a restart due to signal SIGHUP from newsyslog
• the "foo" sub-process detects the closure of the pipe from syslogd and exits too - this has been confirmed in "foo"s own log
• the restarted syslogd starts a new sub-process "foo"
• next, it looks like close_filed() is then called; which causes deadq_enter() to be called, and that results in a SIGKILL to the new "foo" sub-process <--- this should not happen
• syslogd then starts another new sub-process "foo" which runs okay

Reverting line 381 to the old code from lines 390..404 on the left eliminates this problem:

/*
 * Close the procdesc, killing the underlying
 * process (if it is still alive).
 */
(void)close(f->f_procdesc);
f->f_procdesc = -1;
/*
 * The pipe process is guaranteed to be dead now,
 * so remove it from the deadq.
 */
if (f->f_dq != NULL) {
        deadq_remove(f->f_dq);
        f->f_dq = NULL;
}

[jfree]

In D54343#1339846, @fbsd_opal.com wrote:

I am seeing the following:

• my syslogd here has a permanently-running sub-process started with "| exec /path/to/foo"
• at some point in time, syslogd does a restart due to signal SIGHUP from newsyslog
• the "foo" sub-process detects the closure of the pipe from syslogd and exits too - this has been confirmed in "foo"s own log
• the restarted syslogd starts a new sub-process "foo"
• next, it looks like close_filed() is then called; which causes deadq_enter() to be called, and that results in a SIGKILL to the new "foo" sub-process <--- this should not happen
• syslogd then starts another new sub-process "foo" which runs okay

After staring at the code for a while, I don’t see how this can possibly happen. When syslogd restarts, it walks the following call chain:
init() -> closelogfiles() -> close_filed() -> deadq_enter().

Inside of deadq_enter(), the pipe process is put on a queue to be signaled for termination. If the pipe process has already died at this point due to the syslogd closing its end of the pipe, then init() will return and the event loop will address the process death by freeing the process’ resources.

deadq_enter() is only ever given the original process’ procdesc. There is no way it could mis-signal another newly spawned process. That is, unless that newly spawned process closes its end of the pipe, then that new process will be entered into the deadq, but this is intended behavior.

Reverting line 381 to the old code from lines 390..404 on the left eliminates this problem:

/*
 * Close the procdesc, killing the underlying
 * process (if it is still alive).
 */
(void)close(f->f_procdesc);
f->f_procdesc = -1;
/*
 * The pipe process is guaranteed to be dead now,
 * so remove it from the deadq.
 */
if (f->f_dq != NULL) {
        deadq_remove(f->f_dq);
        f->f_dq = NULL;
}

This suggestion reverts the bug fix for the original problem this review was trying to solve. It kills the process immediately at restart time.

The only way I can see something like this happening is if your program is rejecting writes from syslogd over the pipe for some reason.

[fbsd_opal.com]

My logging sub-process is a Perl script that reads stdin (the pipe from syslogd) using a standard Perl read loop:

while (<>) {
     ...
}

Immediately after that loop, the script logs a message (to its own log file) and exit()s.

Here is an except of the syslog with this patch in place:

Jul 22 18:00:00 hbox syslogd: restart
Jul 22 18:00:23 hbox syslogd: Logging subprocess 13679 (exec /home/opal/foo) exited due to signal 9.
Jul 22 19:00:00 hbox syslogd: restart
Jul 22 19:00:26 hbox syslogd: Logging subprocess 16273 (exec /home/opal/foo) exited due to signal 9.
Jul 22 20:00:00 hbox syslogd: restart
Jul 22 20:00:01 hbox syslogd: Logging subprocess 19836 (exec /home/opal/foo) exited due to signal 9.
Jul 22 21:00:00 hbox syslogd: restart
Jul 22 22:00:00 hbox syslogd: restart
Jul 22 22:00:09 hbox syslogd: Logging subprocess 25152 (exec /home/opal/foo) exited due to signal 9.
Jul 22 23:00:00 hbox syslogd: restart
Jul 22 23:00:13 hbox syslogd: Logging subprocess 28320 (exec /home/opal/foo) exited due to signal 9.
Jul 23 00:00:00 hbox syslogd: restart
Jul 23 00:00:17 hbox syslogd: Logging subprocess 35115 (exec /home/opal/foo) exited due to signal 9.

As noted, partially reverting this change causes the kill 9 to not happen.

[jfree]

In D54343#1345224, @fbsd_opal.com wrote:

Here is an except of the syslog with this patch in place:

Jul 22 18:00:00 hbox syslogd: restart
Jul 22 18:00:23 hbox syslogd: Logging subprocess 13679 (exec /home/opal/foo) exited due to signal 9.
Jul 22 19:00:00 hbox syslogd: restart
Jul 22 19:00:26 hbox syslogd: Logging subprocess 16273 (exec /home/opal/foo) exited due to signal 9.
Jul 22 20:00:00 hbox syslogd: restart
Jul 22 20:00:01 hbox syslogd: Logging subprocess 19836 (exec /home/opal/foo) exited due to signal 9.
Jul 22 21:00:00 hbox syslogd: restart
Jul 22 22:00:00 hbox syslogd: restart
Jul 22 22:00:09 hbox syslogd: Logging subprocess 25152 (exec /home/opal/foo) exited due to signal 9.
Jul 22 23:00:00 hbox syslogd: restart
Jul 22 23:00:13 hbox syslogd: Logging subprocess 28320 (exec /home/opal/foo) exited due to signal 9.
Jul 23 00:00:00 hbox syslogd: restart
Jul 23 00:00:17 hbox syslogd: Logging subprocess 35115 (exec /home/opal/foo) exited due to signal 9.

As noted, partially reverting this change causes the kill 9 to not happen.

This seems backwards to me. Your reverted version uses pdkill(2), which sends SIGKILL to the procdesc process immediately. Yet, you're saying your patch does not send SIGKILL, if I'm interpreting correctly.

If you can give me a program and instructions on how to reproduce this, I can debug more. With the information I have now, I am clueless.

[jfree]

Typo on my part. I said:

Your reverted version uses pdkill(2), which sends SIGKILL to the procdesc process immediately.

But I meant:

Your reverted version uses close(2) on the procdesc, which sends SIGKILL to the procdesc process immediately.

Sorry for the confusion.