Bug 714778 - cronie messages end up in /var/log/messages where they do not belong
cronie messages end up in /var/log/messages where they do not belong
Status: CLOSED WONTFIX
Product: Fedora
Classification: Fedora
Component: sysklogd (Show other bugs)
16
x86_64 Linux
unspecified Severity urgent
: ---
: ---
Assigned To: Jeroen van Meeuwen
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-06-20 13:17 EDT by udo
Modified: 2013-02-13 10:29 EST (History)
13 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-02-13 10:29:24 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description udo 2011-06-20 13:17:56 EDT
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.
Comment 1 Tomas Mraz 2011-06-20 15:52:06 EDT
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.
Comment 2 udo 2011-06-21 08:32:48 EDT
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?
Comment 3 Tomas Mraz 2011-06-21 08:54:47 EDT
Do the messages always go into the wrong log or is the behavior random?
Comment 4 udo 2011-06-21 09:05:36 EDT
Always. Very consistent.
Comment 5 Tomas Mraz 2011-06-21 09:13:06 EDT
Does this happen if you restart crond on the system?

Does it happen with selinux set to permissive mode?
Comment 6 udo 2011-06-21 09:48:18 EDT
We restarted the whole system but I can try the cronie restart.
We do not ever use selinux.
Comment 7 Tomas Mraz 2011-06-21 11:33:16 EDT
I'd like to know whether just a restart of cronie when the logs are being written into wrong log fixes the problem.
Comment 8 udo 2011-06-21 11:38:47 EDT
cronie restart doesn't fix it.
Comment 9 Tomas Mraz 2011-06-21 11:59:09 EDT
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?
Comment 10 udo 2011-06-21 12:09:29 EDT
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
Comment 11 Tomas Mraz 2011-06-21 14:33:30 EDT
Hmm and what about lsof of the crond? Does it have /dev/log opened?
Comment 12 udo 2011-06-21 22:39:44 EDT
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
Comment 13 Tomas Mraz 2011-06-22 02:01:53 EDT
I suppose the 5th fd is the /dev/log connection.
Comment 14 udo 2011-06-22 11:20:26 EDT
Could be. Looks like a socket... What info can I provide next to find the cause?
Comment 15 udo 2011-06-22 11:22:01 EDT
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... (?)
Comment 16 Tomas Mraz 2011-06-22 15:34:40 EDT
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).
Comment 17 Lennart Poettering 2011-06-22 16:10:08 EDT
We just keep the fd open due to socket activaton. However as lon as rsyslog is running we do not do anything with it.
Comment 18 Tomas Mraz 2011-06-23 04:03:36 EDT
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.
Comment 19 udo 2011-06-23 08:43:29 EDT
# 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
#
Comment 20 Tomas Mraz 2011-06-23 08:51:41 EDT
Please also stop the systemd-kmsg-syslogd.service and keep the syslogd running.

Still no messages in /var/log/cron ?
Comment 21 udo 2011-06-23 09:13:01 EDT
/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
Comment 22 Tomas Mraz 2011-06-23 09:24:32 EDT
These run-parts messages are duplicated in both /var/log/cron and /var/log/messages?
Comment 23 udo 2011-06-23 09:32:17 EDT
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
Comment 24 Tomas Mraz 2011-06-23 09:48:03 EDT
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?
Comment 25 udo 2011-06-23 10:03:10 EDT
# 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
#
Comment 26 udo 2011-06-23 10:39:23 EDT
# 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
Comment 27 Tomas Mraz 2011-06-23 11:40:51 EDT
(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.)
Comment 28 udo 2011-06-26 02:56:07 EDT
So what can I do to help find the cause of this bug?
Comment 29 Lennart Poettering 2011-06-29 12:37:49 EDT
(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.
Comment 30 udo 2011-06-29 13:08:54 EDT
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.
Comment 31 Tomas Mraz 2011-06-29 14:42:43 EDT
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:' .....
Comment 32 Lennart Poettering 2011-07-04 15:53:01 EDT
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.
Comment 33 udo 2011-07-04 16:02:43 EDT
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)
Comment 34 udo 2011-07-04 16:08:06 EDT
"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?
Comment 35 Michal Schmidt 2011-07-04 16:36:27 EDT
(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.
Comment 36 udo 2011-10-13 10:38:13 EDT
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.
Comment 37 Michal Schmidt 2011-10-13 11:06:03 EDT
sysklogd must be modified to the rules listed in
http://www.freedesktop.org/wiki/Software/systemd/syslog or be removed from
Fedora.
Comment 38 udo 2011-10-13 12:21:44 EDT
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.
Comment 39 udo 2011-10-23 05:33:52 EDT
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.
Comment 40 Michal Schmidt 2011-10-23 12:45:49 EDT
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.
Comment 41 udo 2011-10-23 12:56:18 EDT
# 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...
Comment 42 udo 2011-10-23 12:58:35 EDT
# 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?
Comment 43 udo 2011-10-23 13:05:49 EDT
# /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
Comment 44 Michal Schmidt 2011-10-23 13:16:42 EDT
(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.
Comment 45 Michal Schmidt 2011-10-23 13:18:01 EDT
I see you already did kill it afterwards. Good. Let us know if the bug is still present now.
Comment 46 udo 2011-10-24 10:55:56 EDT
So far stuff looks normal.
Comment 47 udo 2011-10-24 11:00:54 EDT
BTW: ever see what happens when you kill sysklogd before insatlling rsyslog?
Comment 48 Michal Schmidt 2011-10-24 11:36:01 EDT
No, I haven't. Does anything interesting happen?
Comment 49 udo 2011-10-24 11:43:19 EDT
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)
Comment 50 Michal Schmidt 2011-10-24 11:51:30 EDT
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.
Comment 51 udo 2011-12-03 09:17:56 EST
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)
Comment 52 Michal Schmidt 2011-12-05 08:33:51 EST
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
Comment 53 udo 2011-12-05 09:21:18 EST
# 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
Comment 54 Michal Schmidt 2011-12-05 09:43:27 EST
(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
Comment 55 udo 2011-12-05 10:40:41 EST
# 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?
Comment 56 Michal Schmidt 2011-12-05 11:17:24 EST
Yes, stop it.
Comment 57 udo 2011-12-22 12:32:44 EST
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.
Comment 58 Michal Schmidt 2011-12-22 18:14:29 EST
(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.
Comment 59 udo 2011-12-23 08:11:15 EST
How to be sure?
And when will that be solved?
Is that a regression of some sorts?
Comment 60 Bert DeKnuydt 2012-04-20 04:59:21 EDT
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
Comment 61 Fedora End Of Life 2013-01-16 09:26:58 EST
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
Comment 62 Fedora End Of Life 2013-02-13 10:29:28 EST
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.

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