Bug#630538: Vixie cron PID confusion
Hi Christian, Teal, I adopted the package cron a few months ago and will keep ironing out outstanding bug reports, when I can do it. Dear Teal, please can you propose a patch to fix this issue as you suggested it three months ago? Best regards, Georges. On Sat, 15 Apr 2023 14:14:59 +0200 Christian Kastner wrote: > Hi Teal, > > I'm no longer a maintainer of cron, but I was the one last replying to > the original report (can't believe it's been 12 years...) > > On 2023-04-08 12:30, Teal Bauer wrote: > > The same Selective logging patch added a version of the logging in the > > default branch of the fork() switch, so if the -L log levels for "log > > job start" and "log job pid" are set, the starting PID is not logged by > > the child but the parent process instead. > > > > So basically there is now what seems to me to be a "do things right" > > flag - if log level includes 8 (log PIDs) then both CMD and END messages > > are sent by the same process and contain the same correct PIDs: > > > > Apr 8 10:17:56 e02fc37faf65 CRON[27]: (root) CMD ([28] > > /tmp/runner.sh >>/tmp/runner.log) > > Apr 8 10:19:12 e02fc37faf65 CRON[27]: (root) END ([28] > > /tmp/runner.sh >>/tmp/runner.log) > > > > (PID 27 is the cron parent, PID 28 is the command child, PID 29 is the > > PID of the actual command). > > If the log level includes only e.g. "log start" and "log end", then the > > PIDs will differ: > > > > Apr 8 10:14:06 2d9c73749325 CRON[28]: (root) CMD (/tmp/runner.sh > >>>/tmp/runner.log) > > Apr 8 10:15:27 2d9c73749325 CRON[27]: (root) END (/tmp/runner.sh > >>>/tmp/runner.log) > > > > (PID 28 is the command child which sends the CMD message, PID 27 is the > > cron parent which sends the END message, the actual command is PID 29) > > > > I would like to propose (and intend on submitting a patch soon) to > > always log in the same place. > > Ideally, that would be the child process, so that the PID that openlog() > > uses and the PID that cron would log are the same, but I'm not sure > > that's possible in a reliable way. Doing it in the parent is just as > > well for me, though - my original intent was trying to match CMDs to > > ENDs in the logs of a wildly active system. > > > > Curious to hear your thoughts! > > Sounds good to me! > > Best, > Christian > > -- Georges KHAZNADAR et Jocelyne FOURNIER 22 rue des mouettes, 59240 Dunkerque France. Téléphone +33 (0)3 28 29 17 70 signature.asc Description: PGP signature
Bug#630538: Vixie cron PID confusion
Hi Teal, I'm no longer a maintainer of cron, but I was the one last replying to the original report (can't believe it's been 12 years...) On 2023-04-08 12:30, Teal Bauer wrote: > The same Selective logging patch added a version of the logging in the > default branch of the fork() switch, so if the -L log levels for "log > job start" and "log job pid" are set, the starting PID is not logged by > the child but the parent process instead. > > So basically there is now what seems to me to be a "do things right" > flag - if log level includes 8 (log PIDs) then both CMD and END messages > are sent by the same process and contain the same correct PIDs: > > Apr 8 10:17:56 e02fc37faf65 CRON[27]: (root) CMD ([28] > /tmp/runner.sh >>/tmp/runner.log) > Apr 8 10:19:12 e02fc37faf65 CRON[27]: (root) END ([28] > /tmp/runner.sh >>/tmp/runner.log) > > (PID 27 is the cron parent, PID 28 is the command child, PID 29 is the > PID of the actual command). > If the log level includes only e.g. "log start" and "log end", then the > PIDs will differ: > > Apr 8 10:14:06 2d9c73749325 CRON[28]: (root) CMD (/tmp/runner.sh >>>/tmp/runner.log) > Apr 8 10:15:27 2d9c73749325 CRON[27]: (root) END (/tmp/runner.sh >>>/tmp/runner.log) > > (PID 28 is the command child which sends the CMD message, PID 27 is the > cron parent which sends the END message, the actual command is PID 29) > > I would like to propose (and intend on submitting a patch soon) to > always log in the same place. > Ideally, that would be the child process, so that the PID that openlog() > uses and the PID that cron would log are the same, but I'm not sure > that's possible in a reliable way. Doing it in the parent is just as > well for me, though - my original intent was trying to match CMDs to > ENDs in the logs of a wildly active system. > > Curious to hear your thoughts! Sounds good to me! Best, Christian
Bug#630538: Vixie cron PID confusion
I've stumbled onto this bug a little while ago, went through the full debugging cycle and when I wanted to report it, I found this existing bug report. I shelved it and just today came back to it and I would like to add a remark in reply to message #29: You're correct that there is a bug in the logging function, in that the assumptions of UNIXes have changed underneath vixie cron -- namely, syslog does not allow callers to specify a PID at all. The relevant lines from the package source (misc.c): #if defined(SYSLOG) # ifdef LOG_CRON openlog(ProgramName, LOG_PID, LOG_CRON); # else openlog(ProgramName, LOG_PID); # endif syslog(LOG_INFO, "(%s) %s (%s)", username, event, detail); So when logging to syslog, the PID passed to the log function is never used, due to a limitation of syslog. Thus, the fix needs to be made in a different place, and - funnily and frustratingly enough - the fix has already been made (probably in 3.0pl1-117), except it is not used by default! do_command.c is responsible for executing the actual cron command. In the original vixie cron source, log_it(usernm, getpid(), "CMD", x); is called from the child process after fork(). However, the "END" logging (which is not in vixie-cron originally but added by the Selective logging patch) is done by the parent process, thus the logged PIDs will differ when used with Syslog. The same Selective logging patch added a version of the logging in the default branch of the fork() switch, so if the -L log levels for "log job start" and "log job pid" are set, the starting PID is not logged by the child but the parent process instead. So basically there is now what seems to me to be a "do things right" flag - if log level includes 8 (log PIDs) then both CMD and END messages are sent by the same process and contain the same correct PIDs: Apr 8 10:17:56 e02fc37faf65 CRON[27]: (root) CMD ([28] /tmp/runner.sh >>/tmp/runner.log) Apr 8 10:19:12 e02fc37faf65 CRON[27]: (root) END ([28] /tmp/runner.sh >>/tmp/runner.log) (PID 27 is the cron parent, PID 28 is the command child, PID 29 is the PID of the actual command). If the log level includes only e.g. "log start" and "log end", then the PIDs will differ: Apr 8 10:14:06 2d9c73749325 CRON[28]: (root) CMD (/tmp/runner.sh >>/tmp/runner.log) Apr 8 10:15:27 2d9c73749325 CRON[27]: (root) END (/tmp/runner.sh >>/tmp/runner.log) (PID 28 is the command child which sends the CMD message, PID 27 is the cron parent which sends the END message, the actual command is PID 29) I would like to propose (and intend on submitting a patch soon) to always log in the same place. Ideally, that would be the child process, so that the PID that openlog() uses and the PID that cron would log are the same, but I'm not sure that's possible in a reliable way. Doing it in the parent is just as well for me, though - my original intent was trying to match CMDs to ENDs in the logs of a wildly active system. Curious to hear your thoughts! Best Teal
