Description of problem: cronie messages end up in /var/log/messages where they do not belong despite the syslog configuration Version-Release number of selected component (if applicable): cronie-1.4.7-3.fc15.x86_64 How reproducible: Upgrade to Fedora 15 Steps to Reproduce: 1. Upgrade to Fedora 15 2. Wait and see cron jobs being run 3. check /var/log/messages, check /etc/syslog.conf or other syslog conf Actual results: See below Expected results: No con messages in /var/log/messages Additional info: I find multiple of these in messages despite syslog saying cron.none for that file. Tried both sysklogd and rsyslog: Jun 20 18:30:01 bla klogd: /USR/SBIN/CROND[31064]: (root) CMD (LANG=C LC_ALL=C /usr/bin/mrtg /etc/mrtg/mrtg.cfg --lock-file /var/lock/mrtg/mrtg_l --confcache-file /var/lib/mrtg/mrtg.ok) Note the SHOUTING uppercase, note the wrong file.
The uppercase comes from the child process name - it is set to uppercase by cronie to distinguish the process from the main cron daemon. However I have no idea how it happens that the message looks like logged by kernel. Also I am not able to reproduce it yet.
Yet I see it on multiple boxes (4 total, 3 x86_64, 1 i686). So please help me find the common misconfiguration here. I replaced rsyslogd by sysklogd so syslog configuration was refreshed. Boxes were booted a few times in between upgrade and now. So what can I do to help you fix this?
Do the messages always go into the wrong log or is the behavior random?
Always. Very consistent.
Does this happen if you restart crond on the system? Does it happen with selinux set to permissive mode?
We restarted the whole system but I can try the cronie restart. We do not ever use selinux.
I'd like to know whether just a restart of cronie when the logs are being written into wrong log fixes the problem.
cronie restart doesn't fix it.
That's really weird - I was able to reproduce the problem if I temporarily stop the rsyslog and then later start it again - the messages get stored in the kernel buffer and then rsyslog puts them as messages from kernel into the /var/log/messages. Are you really sure that rsyslog (or sysklogd) is started and processes messages sent to /dev/log? What 'lsof -p $(pidof rsyslogd)' (or $(pidof syslogd)) prints?
i686: # lsof -p $(pidof syslogd) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME syslogd 2464 root cwd DIR 3,5 4096 2 / syslogd 2464 root rtd DIR 3,5 4096 2 / syslogd 2464 root txt REG 3,5 35632 7843 /sbin/syslogd syslogd 2464 root mem REG 3,5 142604 108879 /lib/ld-2.14.so syslogd 2464 root mem REG 3,5 1855448 109961 /lib/libc-2.14.so syslogd 2464 root mem REG 3,5 54456 108935 /lib/libnss_files-2.14.so syslogd 2464 root 0u unix 0xf56f9d40 0t0 724733 /dev/log syslogd 2464 root 2w REG 3,6 2876659 367 /var/log/messages syslogd 2464 root 3w REG 3,6 220179 375 /var/log/secure syslogd 2464 root 4w REG 3,6 241791 381 /var/log/maillog syslogd 2464 root 5w REG 3,6 231454 429 /var/log/cron syslogd 2464 root 6w REG 3,6 0 391 /var/log/spooler syslogd 2464 root 7w REG 3,6 0 392 /var/log/boot.log syslogd 2464 root 8w REG 3,6 6567 357 /var/log/authlog syslogd 2464 root 9w CHR 4,11 0t0 45 /dev/tty11 syslogd 2464 root 10u unix 0xf56f9040 0t0 724735 /chroot/named/dev/log syslogd 2464 root 11u unix 0xf56f9380 0t0 724736 /chroot/ntpd/dev/log syslogd 2464 root 12u IPv4 724737 0t0 UDP *:syslog syslogd 2464 root 13w CHR 4,12 0t0 46 /dev/tty12 x86_64: # lsof -p $(pidof syslogd) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME syslogd 17281 root cwd DIR 253,5 4096 2 / syslogd 17281 root rtd DIR 253,5 4096 2 / syslogd 17281 root txt REG 253,5 40184 1809 /sbin/syslogd syslogd 17281 root mem REG 253,5 153400 1360 /lib64/ld-2.14.so syslogd 17281 root mem REG 253,5 1949264 1581 /lib64/libc-2.14.so syslogd 17281 root mem REG 253,5 61632 4772 /lib64/libnss_files-2.14.so syslogd 17281 root 0u unix 0xffff8800c726d3c0 0t0 61903 /dev/log syslogd 17281 root 2w REG 253,1 38801 2208 /var/log/messages syslogd 17281 root 3w REG 253,1 1038 2312 /var/log/secure syslogd 17281 root 4w REG 253,1 0 2553 /var/log/maillog syslogd 17281 root 5w REG 253,1 24437 2706 /var/log/cron syslogd 17281 root 6w REG 253,1 0 2704 /var/log/spooler syslogd 17281 root 7w REG 253,1 0 2705 /var/log/boot.log and another one: # lsof -p $(pidof syslogd) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME syslogd 22625 root cwd DIR 253,9 4096 2 / syslogd 22625 root rtd DIR 253,9 4096 2 / syslogd 22625 root txt REG 253,9 40184 1815 /sbin/syslogd (deleted) syslogd 22625 root DEL REG 253,9 3089 /lib64/ld-2.14.so syslogd 22625 root DEL REG 253,9 3287 /lib64/libc-2.14.so syslogd 22625 root mem REG 253,9 61632 1797 /lib64/libnss_files-2.14.so syslogd 22625 root 0u unix 0xffff8800050dd080 0t0 21303998 /dev/log syslogd 22625 root 2w REG 253,3 262107 107256 /var/log/messages syslogd 22625 root 3w REG 253,3 1637 108227 /var/log/secure syslogd 22625 root 4w REG 253,3 8095 108228 /var/log/maillog syslogd 22625 root 5w REG 253,3 26833 108389 /var/log/cron syslogd 22625 root 6w REG 253,3 0 108229 /var/log/spooler syslogd 22625 root 7w REG 253,3 0 108305 /var/log/boot.log
Hmm and what about lsof of the crond? Does it have /dev/log opened?
i686: # lsof -p $(pidof crond) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME crond 11580 root cwd DIR 3,5 4096 2 / crond 11580 root rtd DIR 3,5 4096 2 / crond 11580 root txt REG 3,8 64684 150198 /usr/sbin/crond crond 11580 root mem REG 3,5 142604 108879 /lib/ld-2.14.so crond 11580 root mem REG 3,5 1855448 109961 /lib/libc-2.14.so crond 11580 root mem REG 3,5 93252 109086 /lib/libaudit.so.1.0.0 crond 11580 root mem REG 3,5 53848 109981 /lib/libpam.so.0.83.0 crond 11580 root mem REG 3,5 19884 109963 /lib/libdl-2.14.so crond 11580 root mem REG 3,5 122652 109972 /lib/libselinux.so.1 crond 11580 root mem REG 3,5 54456 108935 /lib/libnss_files-2.14.so crond 11580 root mem REG 3,8 104490416 111563 /usr/lib/locale/locale-archive crond 11580 root 0u CHR 1,3 0t0 21 /dev/null crond 11580 root 1u CHR 1,3 0t0 21 /dev/null crond 11580 root 2u CHR 1,3 0t0 21 /dev/null crond 11580 root 3uW REG 0,14 6 1751959 /var/run/crond.pid crond 11580 root 4u 0000 0,9 0 18 anon_inode crond 11580 root 5u unix 0xf56fa700 0t0 1751962 socket x86_64: # lsof -p $(pidof crond) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME crond 2310 root cwd DIR 253,5 4096 2 / crond 2310 root rtd DIR 253,5 4096 2 / crond 2310 root txt REG 253,4 64144 1027 /usr/sbin/crond crond 2310 root mem REG 253,5 153400 1360 /lib64/ld-2.14.so crond 2310 root mem REG 253,5 1949264 1581 /lib64/libc-2.14.so crond 2310 root mem REG 253,5 22696 2818 /lib64/libdl-2.14.so crond 2310 root mem REG 253,5 124984 4789 /lib64/libselinux.so.1 crond 2310 root mem REG 253,5 57000 4812 /lib64/libpam.so.0.83.0 crond 2310 root mem REG 253,5 99120 4811 /lib64/libaudit.so.1.0.0 crond 2310 root mem REG 253,5 61632 4772 /lib64/libnss_files-2.14.so crond 2310 root mem REG 253,4 104490448 8493 /usr/lib/locale/locale-archive crond 2310 root 0r CHR 1,3 0t0 6 /dev/null crond 2310 root 1w CHR 1,3 0t0 6 /dev/null crond 2310 root 2w CHR 1,3 0t0 6 /dev/null crond 2310 root 3uW REG 0,14 5 6135 /var/run/crond.pid crond 2310 root 4r 0000 0,8 0 3 anon_inode crond 2310 root 5u unix 0xffff88011c751080 0t0 7266 socket x86_64 2: # lsof -p $(pidof crond) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME crond 3082 root cwd DIR 253,9 4096 2 / crond 3082 root rtd DIR 253,9 4096 2 / crond 3082 root txt REG 253,2 64144 213154 /usr/sbin/crond (deleted) crond 3082 root DEL REG 253,9 1534 /lib64/ld-2.14.so crond 3082 root DEL REG 253,9 3342 /lib64/libc-2.14.so crond 3082 root DEL REG 253,9 47944 /lib64/libdl-2.14.so crond 3082 root DEL REG 253,9 47952 /lib64/libselinux.so.1.#prelink#.odGpgB crond 3082 root DEL REG 253,9 2563 /lib64/libaudit.so.1.0.0.#prelink#.ateN8t crond 3082 root DEL REG 253,9 47992 /lib64/libpam.so.0.83.0.#prelink#.I8s62e crond 3082 root mem REG 253,9 61632 1797 /lib64/libnss_files-2.14.so crond 3082 root mem REG 253,2 104490448 567819 /usr/lib/locale/locale-archive crond 3082 root 0r CHR 1,3 0t0 1040 /dev/null crond 3082 root 1w CHR 1,3 0t0 1040 /dev/null crond 3082 root 2w CHR 1,3 0t0 1040 /dev/null crond 3082 root 3uW REG 0,15 5 9337 /var/run/crond.pid crond 3082 root 4r 0000 0,9 0 1037 anon_inode crond 3082 root 5u unix 0xffff88012b2f9080 0t0 10422 socket # ls -l /dev/log srw-rw-rw- 1 root root 0 Jun 16 15:44 /dev/log
I suppose the 5th fd is the /dev/log connection.
Could be. Looks like a socket... What info can I provide next to find the cause?
Hmm. I can do something like: # fuser -v /dev/log USER PID ACCESS COMMAND /dev/log: root 1 F.... systemd root 1135 F.... systemd-kmsg-sy root 2464 F.... syslogd And none of the boxes show crond as command having /dev/log open... (?)
The 5th fd in the lsof output is the socket for logging. So there is nothing suspicious there. I really think this must be something else than cronie. Perhaps systemd somehow messes up the logging - as I see that it has the /dev/log opened and also switch to systemd is the only major change between F14 and F15 (cronie is in 1.4.7 version in F14).
We just keep the fd open due to socket activaton. However as lon as rsyslog is running we do not do anything with it.
Well it might not really matter whether you are "doing anything with it". Reporter, can you please try 'systemctl stop syslog.socket' ? Then verify that fuser -v /dev/log shows just syslogd and no systemd or systemd-kmsg-syslogd. Will the cronie messages still go to /var/log/messages in that case? I wonder if the systemd-kmsg-syslogd could be the culprit.
# systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl stop syslog.socket # systemctl start syslog.socket Job failed. See system logs and 'systemctl status' for details. [root@recorder mythweb.git]# tail /var/log/messages Jun 23 14:01:01 recorder klogd: /USR/SBIN/CROND[29332]: (root) CMD (run-parts /etc/cron.hourly) Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29341]: finished 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting mcelog.cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29347]: finished mcelog.cron Jun 23 14:41:10 recorder systemd[1]: Socket service systemd-kmsg-syslogd.service already active, refusing. # fuser -v /dev/log USER PID ACCESS COMMAND /dev/log: root 9437 F.... systemd-kmsg-sy root 17281 F.... syslogd #
Please also stop the systemd-kmsg-syslogd.service and keep the syslogd running. Still no messages in /var/log/cron ?
/var/log/cron was not the issue, it had messages. but the excess messages in /var/log/messages are the issue. After stopping the kmsg service and the syslog.socket: # fuser -v /dev/log USER PID ACCESS COMMAND /dev/log: root 17281 F.... syslogd ]# tail /var/log/cron Jun 23 13:01:02 recorder run-parts(/etc/cron.hourly)[29063]: starting mcelog.cron Jun 23 13:01:02 recorder run-parts(/etc/cron.hourly)[29078]: finished mcelog.cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29341]: finished 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting mcelog.cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29347]: finished mcelog.cron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29534]: starting 0anacron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29543]: finished 0anacron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29534]: starting mcelog.cron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29549]: finished mcelog.cron
These run-parts messages are duplicated in both /var/log/cron and /var/log/messages?
Yes, they appear to be so. # cat /etc/syslog.conf # Logging much else clutters up the screen. #kern.* /dev/console # Log anything (except mail) of level info or higher. # Don't log private authentication messages! *.info;mail.none;authpriv.none;cron.none /var/log/messages # The authpriv file has restricted access. authpriv.* /var/log/secure # Log all the mail messages in one place. mail.* -/var/log/maillog # Log cron stuff cron.* /var/log/cron # Everybody gets emergency messages *.emerg * # Save news errors of level crit and higher in a special file. uucp,news.crit /var/log/spooler # Save boot messages also to boot.log local7.* /var/log/boot.log
But I suppose this message: Jun 23 14:01:01 recorder klogd: /USR/SBIN/CROND[29332]: (root) CMD (run-parts /etc/cron.hourly) ...actually is not replicated in /var/log/cron? Because I think this is a different problem The run-parts messages are produced with the logger command in the run-parts script. Duplicating them looks like some bug in the logger command. Note that also there is no klogd: prepended to these messages. Can you try run manually: logger -p cron.notice -t loggertest Testing the logger Is the message in both cron and messages logfiles too?
# grep CRON /var/log/cron # # grep CRON /var/log/messages|wc -l 147 # # logger -p cron.notice -t loggertest Testing the logger # grep Test /var/log/messages Jun 23 16:02:21 recorder klogd: loggertest[31898]: Testing the logger # grep Test /var/log/cron #
# grep 29332 /var/log/cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting mcelog.cron # tail /var/log/cron Jun 23 13:01:02 recorder run-parts(/etc/cron.hourly)[29063]: starting mcelog.cron Jun 23 13:01:02 recorder run-parts(/etc/cron.hourly)[29078]: finished mcelog.cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29341]: finished 0anacron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29332]: starting mcelog.cron Jun 23 14:01:02 recorder run-parts(/etc/cron.hourly)[29347]: finished mcelog.cron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29534]: starting 0anacron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29543]: finished 0anacron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29534]: starting mcelog.cron Jun 23 15:01:02 recorder run-parts(/etc/cron.hourly)[29549]: finished mcelog.cron
(In reply to comment #25) > # grep CRON /var/log/cron > # > # grep CRON /var/log/messages|wc -l > 147 > # > # logger -p cron.notice -t loggertest Testing the logger > # grep Test /var/log/messages > Jun 23 16:02:21 recorder klogd: loggertest[31898]: Testing the logger > # grep Test /var/log/cron > # I suppose the systemd-kmsg-syslog was running here again. It is clear that there is something really botched with the logging in Fedora 15. The interaction of systemd, syslogd, and systemd-kmsg-syslog is the primary cause, that is also clear. Reassigning to systemd again for further evaluation. Lennart, please do not reassign it back to cronie as it is clear that cronie is not the culprit here. (logger command which is not part of cronie behaves the same way.)
So what can I do to help find the cause of this bug?
(In reply to comment #27) > (In reply to comment #25) > > # grep CRON /var/log/cron > > # > > # grep CRON /var/log/messages|wc -l > > 147 > > # > > # logger -p cron.notice -t loggertest Testing the logger > > # grep Test /var/log/messages > > Jun 23 16:02:21 recorder klogd: loggertest[31898]: Testing the logger > > # grep Test /var/log/cron > > # > > I suppose the systemd-kmsg-syslog was running here again. Hmm? I am not sure what this is supposed to be about? You use logger to write to syslog. systemd is not involved with that. It is rsyslog which then writes that to disk, i.e. to /var/log/messages. systemd is not aware of that file. > > It is clear that there is something really botched with the logging in Fedora > 15. The interaction of systemd, syslogd, and systemd-kmsg-syslog is the primary cause, that is also clear. Most likely the rsyslog configuration simply configures things that way. > Reassigning to systemd again for further evaluation. Lennart, please do not > reassign it back to cronie as it is clear that cronie is not the culprit here. > (logger command which is not part of cronie behaves the same way.) Well, systemd has no business in writing log messages to disk, so this has nothing to do with systemd. If I understand this correctly, then the bug is that messages in the "cron" facility get written to /var/log/messages instead of /var/log/cron? That's purely rsyslog business.
sysklogd shows the same behaviour on multiple boxes. next is the weird thing that on two boxes (not all!) the issue has gone away. so now we have to find out _why_. but I'll be offline for a few days starting tomorrow.
No, this is in no way that simple as Lennart thinks. There are probably two bugs - one is possible problem in sysklogd - these are the duplicate run-parts(/etc/cron.hourly) messages above (note that there is no 'klogd:' in these messages). The other bug is probably a race between syslogd and systemd-kmsg-syslogd when they are both listening on the /dev/log - this causes the messages with 'klogd:' .....
Hmmm, sysklogd should stop systemd-kmsg-syslogd if it starts up, the same way as rsyslog is doing it. But that said, I am not sure why we still have sysklogd in the repo even.
Aside from freedom of choice, does it matter? The problem appears and now partly disappeared. I can try stuff early tomorrow morning if you have any things i could try. (need to recover from insomnia)
"sysklogd should stop systemd-kmsg-syslogd if it starts up, the same way as rsyslog is doing it." How is this done and how can we verify that this attempted at all or and/or maybe not succeeding?
(In reply to comment #34) rsyslog.service stops systemd-kmsg-syslogd.service in its ExecStartPre step. To verify this you can check the status of systemd-kmsg-syslogd.service after rsyslog.service is started, or trace this sequence in systemd's debug logs.
Rebooted this box for the network problem of https://bugzilla.redhat.com/show_bug.cgi?id=744523 and noticed that the cron-related logging in dmesg and messages reappeared. :-( Nothing syslogd related has changed.
sysklogd must be modified to the rules listed in http://www.freedesktop.org/wiki/Software/systemd/syslog or be removed from Fedora.
removing sysklogd and installing rsyslog does not change the logging of cron stuff into dmesg and messages. installing sysklogd was a means to see if this was syslog daemon related or not.
I repeat comment #38: Even with no sysklogd running, installed rsyslog instead, I get the `spam` logging in dmesg and messages. cron stuff does not belong there. Please fix.
I cannot reproduce the bug. Please post the output of "systemctl status systemd-kmsg-syslogd.service rsyslog.service". Also please re-do the experiment from comment #24 with rsyslog.
# systemctl status systemd-kmsg-syslogd.service rsyslog.service systemd-kmsg-syslogd.service - Syslog Kernel Log Buffer Bridge Loaded: loaded (/lib/systemd/system/systemd-kmsg-syslogd.service) Active: active (running) since Thu, 13 Oct 2011 17:20:01 +0200; 1 weeks and 3 days ago Main PID: 11959 (systemd-kmsg-sy) Status: "Processing messages..." CGroup: name=systemd:/system/systemd-kmsg-syslogd.service └ 11959 /lib/systemd/systemd-kmsg-syslogd rsyslog.service - System Logging Service Loaded: loaded (/lib/systemd/system/rsyslog.service) Active: failed since Thu, 13 Oct 2011 17:18:42 +0200; 1 weeks and 3 days ago Main PID: 11947 (code=exited, status=1/FAILURE) CGroup: name=systemd:/system/rsyslog.service Thus: # ls -l /var/log/cron* -rw------- 1 root root 0 Oct 23 03:18 /var/log/cron -rw------- 1 root root 462943 Oct 2 03:22 /var/log/cron-20111002 -rw------- 1 root root 464033 Oct 9 03:34 /var/log/cron-20111009 -rw------- 1 root root 270710 Oct 16 03:06 /var/log/cron-20111016 -rw------- 1 root root 0 Oct 16 03:06 /var/log/cron-20111023 # ls -l /var/log/messages* -rw------- 1 root root 0 Oct 23 03:18 /var/log/messages -rw------- 1 root root 14135702 Oct 2 03:22 /var/log/messages-20111002 -rw------- 1 root root 11931575 Oct 9 02:34 /var/log/messages-20111009 -rw------- 1 root root 1095522 Oct 16 03:05 /var/log/messages-20111016 -rw------- 1 root root 0 Oct 16 03:06 /var/log/messages-20111023 so a freshly installed rsyslog (13-oct-2011) fails at night within a few days. how come? obviosly I did not check the logs not growing...
# systemctl start rsyslog.service # systemctl status systemd-kmsg-syslogd.service rsyslog.service systemd-kmsg-syslogd.service - Syslog Kernel Log Buffer Bridge Loaded: loaded (/lib/systemd/system/systemd-kmsg-syslogd.service) Active: inactive (dead) since Sun, 23 Oct 2011 18:56:35 +0200; 58s ago Main PID: 11959 (code=exited, status=0/SUCCESS) Status: "Shutting down..." CGroup: name=systemd:/system/systemd-kmsg-syslogd.service rsyslog.service - System Logging Service Loaded: loaded (/lib/systemd/system/rsyslog.service) Active: failed since Sun, 23 Oct 2011 18:57:32 +0200; 1s ago Process: 23274 ExecStart=/sbin/rsyslogd -n $SYSLOGD_OPTIONS (code=exited, status=1/FAILURE) Process: 23272 ExecStartPre=/bin/systemctl stop systemd-kmsg-syslogd.service (code=exited, status=0/SUCCESS) CGroup: name=systemd:/system/rsyslog.service So why doesn't it start? This was the recommended syslog facilty. What about systemd-kmsg-syslogd.service?
# /sbin/rsyslogd -n -d (......) 9304.965259806:7ffe244ce720: Called LogError, msg: WARNING: rsyslogd is running in compatibility mode. Automatically generated config directives may interfer with your rsyslog.conf settings. We suggest upgrading your config and adding -c5 as the first rsyslogd option. 9304.965344874:7ffe244ce720: MsgSetTAG in: len 9, pszBuf: rsyslogd: 9304.965360950:7ffe244ce720: MsgSetTAG exit: pMsg->iLenTAG 9, pMsg->TAG.szBuf: rsyslogd: rsyslogd: WARNING: rsyslogd is running in compatibility mode. Automatically generated config directives may interfer with your rsyslog.conf settings. We suggest upgrading your config and adding -c5 as the first rsyslogd option. 9304.965395018:7ffe244ce720: Writing pidfile /var/run/syslogd.pid. Pidfile (and pid) already exist. # ps -ef|grep `cat /var/run/syslogd.pid` root 3665 1 0 Oct12 ? 00:00:01 syslogd -m 0 root 23433 32385 0 19:02 pts/0 00:00:00 grep --color=auto 3665 So we have the pid, there is a process but a restart does not kill it and thus not successfully start it. # kill -9 3665 # service rsyslog start Starting rsyslog (via systemctl): [ OK ] # systemctl status systemd-kmsg-syslogd.service rsyslog.service systemd-kmsg-syslogd.service - Syslog Kernel Log Buffer Bridge Loaded: loaded (/lib/systemd/system/systemd-kmsg-syslogd.service) Active: inactive (dead) since Sun, 23 Oct 2011 19:04:08 +0200; 7s ago Process: 23401 ExecStart=/lib/systemd/systemd-kmsg-syslogd (code=exited, status=0/SUCCESS) Status: "Shutting down..." CGroup: name=systemd:/system/systemd-kmsg-syslogd.service rsyslog.service - System Logging Service Loaded: loaded (/lib/systemd/system/rsyslog.service) Active: active (running) since Sun, 23 Oct 2011 19:04:08 +0200; 7s ago Process: 23454 ExecStartPre=/bin/systemctl stop systemd-kmsg-syslogd.service (code=exited, status=0/SUCCESS) Main PID: 23457 (rsyslogd) CGroup: name=systemd:/system/rsyslog.service └ 23457 /sbin/rsyslogd -n -c 5
(In reply to comment #43) > # ps -ef|grep `cat /var/run/syslogd.pid` > root 3665 1 0 Oct12 ? 00:00:01 syslogd -m 0 This is still the old syslogd running. It must be preventing rsyslog from starting. Kill it.
I see you already did kill it afterwards. Good. Let us know if the bug is still present now.
So far stuff looks normal.
BTW: ever see what happens when you kill sysklogd before insatlling rsyslog?
No, I haven't. Does anything interesting happen?
part of dmesg: Oct 24 16:59:33 recorder kernel: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder kernel: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld74 o[2]kg18:ld74 od74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld18:ld74 o[2]kod18::ld744ld74 o[2]kg18:ld74 od74 o[2]kg18:ld74 o[2[2]kg18:ld74 o[2]kg18:kg18:ld74 o[2]4 o[2<kg18:ld74 o[2]kg182]kg12]kg18:ld74 o[2]kg18:ld74 o[2]kg18:44 o[2]ko[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 od74 o[2]kg18:ld74 o[2]kg18:8:ld74ld74 o[2]ko[2]kg18:ld74 o[2]kg124 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[74 o[2]kg18:ld74 o[2]g18:ld74 o[2]o[2]k<kg12]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[24 o[2]kg18:ld74 o[2]kogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]:284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17 Oct 24 16:59:33 recorder klogd: 284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[177284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: k Oct 24 16:59:33 recorder klogd: logd[17284]: k Oct 24 16:59:33 recorder klogd: klogd[17284]: logd[17284]: k Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: logd[17284]: k Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: lologd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]:g[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 Oct 24 16:59:33 recorder klogd: >o[2]o[2]k<kg18:ld74 g18:l4ld74 o[2]kg18:g18:l4ld74 o[2]kg18:ld78:g18:l4ld74 o[2]kg18:ld74 o[2]o[2]k<kg18:lg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld74 ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld74 o[2] o[2]kg18:ld74 o[2]o[2]k<kg18:ld74 o[2]kg18]kg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld78:ld74 o[2]kg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld78:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:g18:l4ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[74 o[2]o[2]k<kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:g18:l4lg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:lg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:g18:l4ld74 o[2]kg18:lg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:g18:l4ld74 o[2]kg18:lg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:lg18:ld74 18:l4ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2] o[2g18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[78] ld74 o[2]kg18:ld74 ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:lg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld78:ld74 o[ Oct 24 16:59:33 recorder klogd: >o[2]2]kg18:ld74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:g18:l<kg18:ld74 o[2]o[2]k<kg18:ld74 o[2]kg18:g18]k<kg18:ld74 o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:lg18:ld74 o[2]kg18:g18:l4ld74 o[2]kg[2]kg18:ld74 o[2]kg18:g18:l4ld74 o[2]kg18:ld74 o[2] o[2]kg18:ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:lgd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: kl Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: ogd[17284]: lo Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: gd[17284]: k Oct 24 16:59:33 recorder klogd: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284]: klogd[17284:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld78:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2] o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:ld74 l4ld74 d74 Oct 24 16:59:33 recorder klogd: >o[2]kg18:g18:44ld74 o[2]kg18::kg18<kg18:ld74 o[2]kg18::ld744ld74 o[2]kg18]kg18:ld74 o[2 Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld74 o[2]kg18:ld78::ld744ld74 o[2]kg18:ld74 o[2]kg18:ld74 od744ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]]ko[2 Oct 24 16:59:33 recorder klogd: >o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18:lg18::ld18:ld74 o[2]]kg18<kg18:ld74 o[2]kg18]kg18:ld74 o[2]kg18:ld74 o[2]kg18::ld744ld78:ld74 o[2]kg18:ld74 o[2]kg18:ld74 o[2]kg18]kg18:ld74 o[2 (etc)
Right. It's a feedback loop. When you kill syslogd, anything that writes to /dev/log triggers the activation of systemd-kmsg-syslogd.service. 1. systemd-kmsg-syslogd.service writes the message to the dmesg buffer. 2. klogd reads the dmesg buffer and feeds it to /dev/log. 3. Goto 1 BTW, sysklogd's initscript kills klogd first before killing syslogd. Anyway, sysklogd is going away. See bug 748495.
Upgraded to Fedora 16. [root@recorder ~]# rpm -q sysklogd package sysklogd is not installed [root@recorder ~]# rpm -q rsyslog rsyslog-5.8.5-1.fc16.x86_64 [root@recorder ~]# dmesg|tail run-parts(/etc/cron.hourly)[3818]: starting mcelog.cron systemd-logind[4949]: Removed session c37. /USR/SBIN/CROND[3962]: (root) CMD (run-parts /etc/cron.hourly) run-parts(/etc/cron.hourly)[3973]: starting mcelog.cron /USR/SBIN/CROND[4073]: (root) CMD (run-parts /etc/cron.hourly) run-parts(/etc/cron.hourly)[4076]: starting 0anacron run-parts(/etc/cron.hourly)[4088]: finished mcelog.cron systemd-logind[4949]: Removed session c39. systemd-logind[4949]: New session c40 of user mythtv. /USR/SBIN/CROND[4116]: (mythtv) CMD (/usr/bin/mythbackend --resched > /dev/null)
If you're getting the messages logged to dmesg long after the system has booted, two possibilities come to mind: - rsyslog is not actually running. Check: systemctl status syslog.socket rsyslog.service - cron is configured to log there. Check: systemctl show -p StandardOutput -p StandardError crond.service
# systemctl status syslog.socket rsyslog.service syslog.socket - Syslog Socket Loaded: loaded (/lib/systemd/system/syslog.socket; static) Active: active (running) since Fri, 02 Dec 2011 11:05:27 +0100; 3 days ago CGroup: name=systemd:/system/syslog.socket rsyslog.service - System Logging Service Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled) Active: active (running) since Fri, 02 Dec 2011 11:05:35 +0100; 3 days ago Main PID: 2504 (rsyslogd) CGroup: name=systemd:/system/rsyslog.service └ 2504 /sbin/rsyslogd -n -c 5 # systemctl show -p StandardOutput -p StandardError crond.service StandardOutput=syslog StandardError=syslog
(In reply to comment #53) > # systemctl show -p StandardOutput -p StandardError crond.service > StandardOutput=syslog > StandardError=syslog I'm getting "inherit" for StandardError, but "syslog" should work too. Nothing seems wrong here. Maybe the kernel log buffer bridge is running (it should have been stopped during the start of rsyslog). Check: systemctl status systemd-kmsg-syslogd.service
# systemctl status systemd-kmsg-syslogd.service systemd-kmsg-syslogd.service - Syslog Kernel Log Buffer Bridge Loaded: loaded (/lib/systemd/system/systemd-kmsg-syslogd.service; static) Active: active (running) since Fri, 02 Dec 2011 11:17:47 +0100; 3 days ago Main PID: 3695 (systemd-kmsg-sy) Status: "Processing messages..." CGroup: name=systemd:/system/systemd-kmsg-syslogd.service └ 3695 /lib/systemd/systemd-kmsg-syslogd So it is running. I can manually stop it?
Yes, stop it.
It was running once again. I did not renable it. I perhaps happened after going from runlevel5-ish to 3-ish. How to prevent such stuff? # systemctl status systemd-kmsg-syslogd.service systemd-kmsg-syslogd.service - Syslog Kernel Log Buffer Bridge Loaded: loaded (/lib/systemd/system/systemd-kmsg-syslogd.service; static) Active: active (running) since Mon, 12 Dec 2011 19:29:43 +0100; 1 weeks and 2 days ago Main PID: 25849 (systemd-kmsg-sy) Status: "Processing messages..." CGroup: name=systemd:/system/systemd-kmsg-syslogd.service └ 25849 /lib/systemd/systemd-kmsg-syslogd # grep 'Dec 12 19' messages* messages-20111218:Dec 12 19:01:01 recorder systemd-logind[2364]: New session c202 of user root. messages-20111218:Dec 12 19:01:02 recorder systemd-logind[2364]: Removed session c202. messages-20111218:Dec 12 19:05:01 recorder systemd-logind[2364]: New user mythtv logged in. messages-20111218:Dec 12 19:05:01 recorder systemd-logind[2364]: New session c203 of user mythtv. messages-20111218:Dec 12 19:05:02 recorder systemd-logind[2364]: Removed session c203. messages-20111218:Dec 12 19:29:42 recorder gdm-simple-slave[3172]: WARNING: Freeing conversation 'gdm-password' with active job messages-20111218:Dec 12 19:29:42 recorder gdm-simple-slave[3172]: GLib-WARNING: Failed to read from child watch wake up pipe: Interrupted system call messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: dbus disconnected; disconnecting dbus clients... messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: disconnect client: /org/gnome/SessionManager/Client1 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: dbus disconnected, not restarting application messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmStore: Unreffing object: 0x1f4dd10 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmClient: disposing /org/gnome/SessionManager/Client1 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: disconnect client: /org/gnome/SessionManager/Client2 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: disconnect for app 'at-spi-registryd.desktop' messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: dbus disconnected, not restarting application messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmStore: Unreffing object: 0x1f4d700 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmClient: disposing /org/gnome/SessionManager/Client2 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmStore: emitting removed for /org/gnome/SessionManager/Client2 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: Client removed: /org/gnome/SessionManager/Client2 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmStore: emitting removed for /org/gnome/SessionManager/Client1 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: Client removed: /org/gnome/SessionManager/Client1 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GdmSignalHandler: handling signal 15 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GdmSignalHandler: Found 1 callbacks messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GdmSignalHandler: running 15 handler: 0x41bf30 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): Got callback for signal 15 messages-20111218:Dec 12 19:29:43 recorder gnome-session[3306]: DEBUG(+): GsmManager: Logout called messages-20111218:Dec 12 19:29:43 recorder kernel: Adding 2097148k swap on /dev/mapper/swap. Priority:0 extents:1 across:2097148k messages-20111218:Dec 12 19:29:43 recorder rsyslogd: imuxsock: recvfrom UNIX: Resource temporarily unavailable messages-20111218:Dec 12 19:29:44 recorder gnome-session[3306]: DEBUG(+): GsmManager: query end session timed out messages-20111218:Dec 12 19:29:44 recorder gnome-session[3306]: WARNING: Client '/org/gnome/SessionManager/Client3' failed to reply before timeout messages-20111218:Dec 12 19:29:44 recorder gnome-session[3306]: DEBUG(+): GsmManager: query end session complete messages-20111218:Dec 12 19:29:48 recorder systemd[1]: systemd-logind.service: main process exited, code=exited, status=1 messages-20111218:Dec 12 19:29:48 recorder avahi-daemon[2355]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.10.99. messages-20111218:Dec 12 19:29:48 recorder avahi-daemon[2355]: avahi-daemon 0.6.30 exiting. messages-20111218:Dec 12 19:29:48 recorder NetworkManager[17191]: <warn> disconnected by the system bus. messages-20111218:Dec 12 19:29:48 recorder NetworkManager[17191]: <info> caught signal 15, shutting down normally. messages-20111218:Dec 12 19:29:48 recorder NetworkManager[17191]: <warn> quit request received, terminating... messages-20111218:Dec 12 19:29:48 recorder NetworkManager[17191]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory) messages-20111218:Dec 12 19:29:48 recorder NetworkManager[17191]: <info> exiting (success) messages-20111218:Dec 12 19:29:49 recorder dbus[25910]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:29:49 recorder dbus-daemon[25910]: dbus[25910]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:29:49 recorder dbus[25910]: [system] Successfully activated service 'org.freedesktop.systemd1' messages-20111218:Dec 12 19:29:49 recorder systemd[1]: Unit abrtd.service entered failed state. messages-20111218:Dec 12 19:29:49 recorder dbus-daemon[25910]: dbus[25910]: [system] Rejected send message, 2 matched rules; type="signal", sender=":1.0" (uid=48 pid=18501 comm="/usr/sbin/httpd -k start ") interface="org.freedesktop.systemd1.Activator" member="ActivationRequest" error name="(unset)" requested_reply="0" destination="org.freedesktop.systemd1" (uid=0 pid=1 comm="/bin/systemd --log-level info --log-target syslog-") messages-20111218:Dec 12 19:29:49 recorder dbus[25910]: [system] Rejected send message, 2 matched rules; type="signal", sender=":1.0" (uid=48 pid=18501 comm="/usr/sbin/httpd -k start ") interface="org.freedesktop.systemd1.Activator" member="ActivationRequest" error name="(unset)" requested_reply="0" destination="org.freedesktop.systemd1" (uid=0 pid=1 comm="/bin/systemd --log-level info --log-target syslog-") messages-20111218:Dec 12 19:29:49 recorder systemd[1]: RequestName() failed: Access denied messages-20111218:Dec 12 19:30:14 recorder dbus-daemon[25910]: process 25910: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009. messages-20111218:Dec 12 19:30:14 recorder dbus-daemon[25910]: This is normally a bug in some application using the D-Bus library. messages-20111218:Dec 12 19:30:14 recorder dbus-daemon[25910]: D-Bus not built with -rdynamic so unable to print a backtrace messages-20111218:Dec 12 19:30:14 recorder systemd[1]: dbus.service: main process exited, code=killed, status=6 messages-20111218:Dec 12 19:30:15 recorder dbus-daemon[25923]: dbus[25923]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:30:15 recorder dbus[25923]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:30:15 recorder dbus-daemon[25923]: dbus[25923]: [system] Successfully activated service 'org.freedesktop.systemd1' messages-20111218:Dec 12 19:30:15 recorder dbus[25923]: [system] Successfully activated service 'org.freedesktop.systemd1' messages-20111218:Dec 12 19:30:15 recorder systemd[1]: RequestName() failed: Access denied messages-20111218:Dec 12 19:30:40 recorder dbus[25923]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25923]: dbus[25923]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25923]: process 25923: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009. messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25923]: This is normally a bug in some application using the D-Bus library. messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25923]: D-Bus not built with -rdynamic so unable to print a backtrace messages-20111218:Dec 12 19:30:40 recorder systemd[1]: dbus.service: main process exited, code=killed, status=6 messages-20111218:Dec 12 19:30:40 recorder dbus[25931]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:30:40 recorder dbus[25931]: [system] Successfully activated service 'org.freedesktop.systemd1' messages-20111218:Dec 12 19:30:40 recorder dbus[25931]: [system] Rejected send message, 2 matched rules; type="signal", sender=":1.0" (uid=48 pid=18501 comm="/usr/sbin/httpd -k start ") interface="org.freedesktop.systemd1.Activator" member="ActivationRequest" error name="(unset)" requested_reply="0" destination="org.freedesktop.systemd1" (uid=0 pid=1 comm="/bin/systemd --log-level info --log-target syslog-") messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25931]: dbus[25931]: [system] Successfully activated service 'org.freedesktop.systemd1' messages-20111218:Dec 12 19:30:40 recorder dbus-daemon[25931]: dbus[25931]: [system] Rejected send message, 2 matched rules; type="signal", sender=":1.0" (uid=48 pid=18501 comm="/usr/sbin/httpd -k start ") interface="org.freedesktop.systemd1.Activator" member="ActivationRequest" error name="(unset)" requested_reply="0" destination="org.freedesktop.systemd1" (uid=0 pid=1 comm="/bin/systemd --log-level info --log-target syslog-") messages-20111218:Dec 12 19:31:05 recorder dbus[25931]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out messages-20111218:Dec 12 19:31:05 recorder dbus-daemon[25931]: dbus[25931]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out messages-20111218:Dec 12 19:31:05 recorder dbus-daemon[25931]: process 25931: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009. messages-20111218:Dec 12 19:31:05 recorder dbus-daemon[25931]: This is normally a bug in some application using the D-Bus library. messages-20111218:Dec 12 19:31:05 recorder dbus-daemon[25931]: D-Bus not built with -rdynamic so unable to print a backtrace messages-20111218:Dec 12 19:31:05 recorder systemd[1]: dbus.service: main process exited, code=killed, status=6 messages-20111218:Dec 12 19:31:05 recorder dbus-daemon[25946]: dbus[25946]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:31:05 recorder dbus[25946]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: avahi-daemon 0.6.30 starting up. messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: Successfully called chroot(). messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: Successfully dropped remaining capabilities. messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: Loading service file /services/udisks.service. messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.10.99. messages-20111218:Dec 12 19:31:05 recorder avahi-daemon[25949]: Registering HINFO record with values 'X86_64'/'LINUX'. messages-20111218:Dec 12 19:31:06 recorder avahi-daemon[25949]: Server startup complete. Host name is recorder.local. Local service cookie is 414448848.
(In reply to comment #57) > I perhaps happened after going from runlevel5-ish to 3-ish. Then it's likely another symptom of bug 708537.
How to be sure? And when will that be solved? Is that a regression of some sorts?
I got similar with systemd-37-17.fc16.x86_64 rsyslog-5.8.7-1.fc16.x86_64 but only after an init 5 to init 3 to init 5 excursion. Lots of these might be related too? Apr 20 03:47:01 triton rsyslogd: imuxsock: recvfrom UNIX: Resource temporarily unavailable
This message is a reminder that Fedora 16 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 16. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '16'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 16's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 16 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged to click on "Clone This Bug" and open it against that version of Fedora. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Fedora 16 changed to end-of-life (EOL) status on 2013-02-12. Fedora 16 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. Thank you for reporting this bug and we are sorry it could not be fixed.