man cron says:
A higher loglevel (2) will
cause cron to log also the end of all cronjobs, which can be
useful to audit the behaviour of tasks run by cron.
in fact, the logged pid on startup ist higher than the pid of the
terminated cron job. Mostly it's off by one but on a rather loaded
system the difference might be more than that.
Unfortunately this is exactly when you would really need this feature
to work precisely so one could reliably correlate the start- and stop-times
of every job.
tag 609780 confirmed thanks Yes, this was introduced in -95. The issue here is that it's the child process forked by cron sends the "CMD" message and the parent sends the "END". The patch should be easy to adjust so that the pid of the children is stored and used for the END (i.e. the log should not use getpid()). We will try to fix this in a next cron package release. Regards Javier
We believe that the bug you reported is fixed in the latest version of
cron, which is due to be installed in the Debian FTP archive:
cron_3.0pl1-117.diff.gz
to main/c/cron/cron_3.0pl1-117.diff.gz
cron_3.0pl1-117.dsc
to main/c/cron/cron_3.0pl1-117.dsc
cron_3.0pl1-117_i386.deb
to main/c/cron/cron_3.0pl1-117_i386.deb
A summary of the changes between this version and the previous one is
attached.
Thank you for reporting the bug, which will now be closed. If you
have further comments please address them to 609780@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.
Debian distribution maintenance software
pp.
Christian Kastner <debian@kvr.at> (supplier of updated cron package)
(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@debian.org)
Format: 1.8
Date: Sun, 08 May 2011 01:21:15 +0200
Source: cron
Binary: cron
Architecture: source i386
Version: 3.0pl1-117
Distribution: unstable
Urgency: low
Maintainer: Javier Fernandez-Sanguino Pen~a <jfs@debian.org>
Changed-By: Christian Kastner <debian@kvr.at>
Description:
cron - process scheduling daemon
Closes: 478967 537073 578856 579640 609780 615855 622645 625491 625493 625495 627859
Changes:
cron (3.0pl1-117) unstable; urgency=low
.
* Makefile:
- Fixed integration of cron-internal debug code into the package building
process. Instead of having to modify debian/rules, this can now driven by
DEB_BUILD_OPTIONS=debug
- Removed hard-coded compiler flags, honoring those provided by
dpkg-buildflags instead
* do_command.c:
- When logging the end of cron jobs, log the PID of the actually exec'ed
user command, not the PID of the parent. Closes: #609780
* database.c:
- Split crontab security checks (type, owner, mode, links) into separate
tests with individual error messages instead of the cryptic message
"WRONG INODE INFO". Closes: #625493
- Extended the ability to recover from broken symlinks (added in -110) to
also recover from failed security checks above. Fixes to these were not
being detected as cron only looks at mtime. Closes: #625495
- Also recover from syntax errors. Fixes to these did change mtime, but
were ignored as cron permanently removes broken crontabs from its
database of files to check. Closes: #627859
* cron.8:
- Documented the fact that /etc/crontab and files in /etc/cron.d must not
be group- or other-writable. Closes: #625491, LP: #741979
* crontab.5:
- Specify parse order of crontabs (thanks, Jonathan Amery). Closes: #622645
* debian/control:
- Bumped Standards-Version to 3.9.2 (no changes needed)
- Added missing Build-Depends on libaudit-dev
- Removed Conflicts for nonexistent package suidmanager
- Removed Conflicts for lockfile-progs (which should have been a Breaks
anyway) as we no longer rely on it, we use flock from util-linux instead
- Changed architecture-specific Build-Depends on libselinux1-dev to
linux-any instead of negating all other OSes
* debian/cron.default:
- Merged the LSBNAMES option with EXTRA_OPTS. Both where used to pass
options to the daemon, making one of them redundant
- Added the ability to disable the daily lost+found check by setting the
new variable CHECK_LOSTFOUND to "no". Closes: #579640
* debian/cron.init:
- Don't call start-stop-daemon directly, use LSB init functions instead.
Among other things, this works around the cron daemon not deleting its
pidfile from /var/run/. Closes: #615855
- Added $network to Should-Start
* debian/rules:
- Converted to dh syntax. This included replacing some manually executed
steps with debhelper file-automated ones (eg: cron.man, cron.examples)
to lessen clutter
- Completely rewrote the PAM/SELinux/audit integration parts. PAM support
was being skipped on kfreebsd and hurd, and audit support was completely
broken. From now on:
+ PAM is enabled by default on all platforms
+ SELinux is enabled by default on linux-any
+ audit is disabled by default on all platforms
All of these can be driven by DEB_BUILD_OPTIONS (see debian/rules)
- Do not compress example perl scripts
* debian/{prerm,postrm,postinst}:
- Let dh_installinit manage stopping/(re)starting of jobs instead of
calling invoke-rc.d ourselves
* debian/standard.daily:
- Backup of /etc/{passd,group} is no longer performed by cron; the task
was handed over to src:shadow (see #554170). In Squeeze, this task will
be performed redundantly by both packages (as discussed on
debian-release)
- Rewrite locking and lost+found-checking code, based on a submission to
the BTS by Justin B. Rye. Closes: #478967, #537073, LP: #257367
- Parse /etc/mtab instead of /proc/mounts; the former makes handling bind
mounts easier. Closes: #578856
- Pull in /etc/cron/default for CHECK_LOSTFOUND (see above)
* debian/copyright:
- Convert to DEP5 format (r173)
* debian/watch:
- Added watch file to silence a lintian warning, even though the last
upstream release was in 2004
* Packaging (general): removed a lot of cruft which seems to have accumulated
over time. This included all the cron-se stuff, which appears to have been
a remnant from the SELinux integration process, and was either not being
used anymore or completely broken. Also, the patches/ directory was
removed, as that location has a specific meaning and the patches in there
were no longer relevant.
Checksums-Sha1:
b05295fceecdd9702c66dfb3b561c0f0bb1481f9 1219 cron_3.0pl1-117.dsc
1d69b6cd9eb94bd0201f70700892028676a7e874 88976 cron_3.0pl1-117.diff.gz
43c7665efa16c0eb55401cb6145026f56bae31a9 95814 cron_3.0pl1-117_i386.deb
Checksums-Sha256:
6719500e6714d797b21bc1dccc44d03332a909f4a76832515e6c0b3856dc4927 1219 cron_3.0pl1-117.dsc
1705799cac874cfa171064d8a9764140fcf3618c8f004e01f5eeda5dd47898e7 88976 cron_3.0pl1-117.diff.gz
28d7f2917dc40e211b269e41d7f9e0661c9a1167a6297a49db780d21c1e73fbb 95814 cron_3.0pl1-117_i386.deb
Files:
ce23eb8cacdfbeefdd79f77bbb87fbcb 1219 admin important cron_3.0pl1-117.dsc
757abb9a1f1c65da068d2e1cb945996b 88976 admin important cron_3.0pl1-117.diff.gz
a4c1e1d0ecfbd1253f4e7cb59bec6a2a 95814 admin important cron_3.0pl1-117_i386.deb
iD8DBQFN5BSOsandgtyBSwkRAj03AJ4pRKEmbLXXN2LLWI/DxGtDAqdKTwCeM3jL
l8/VkIFBH9WaJWiSZrQDr4k=
=DDkG
-----END PGP SIGNATURE-----
reopen 609780 thanks I noticed by coincidence that this is not entirely fixed, therefore reopening. When running cron with the process debugging code on, it works as expected. In regular mode, however, does not: the reported start pid is that of the parent process instead of the child process.
clone 609780 -1
retitle -1 cron: messages are logged with wrong PID
thanks
The reason for this is a subtle but serious bug in the logging function,
void log_it(char *username, int xpid, char *event, char *detail)
namely that the implementation simply ignores the PID value passed as
the second argument. The actual output in the logfile is simply the PID
of the child when openlog() was called. The bug did not manifest itself
in debug mode because it prints the function arguments as they were passed.
I'm cloning this bug because I'm not sure if it is fixable in general.
The start/stop PID, however, certainly is, so it should be tracked
separately.
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
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...) Sounds good to me! Best, Christian
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.