rsyslog hangs during upgrade

[Kees Cook]

Binary package hint: rsyslog

Setting up rsyslog (4.2.0-1ubuntu1) ...

Creating config file /etc/rsyslog.d/50-default.conf with new version
 * Starting enhanced syslogd rsyslogd
...hangs here...

pstree -alp shows:

  ├─sshd,2059
  │ ├─sshd,2668
  │ │ └─sshd,2677
  │ │ └─bash,2678
  │ │ └─apt-get,2746 dist-upgrade
  │ │ └─dpkg,6249 --status-fd 20 --configure libc6-dev libc6-i686 libgomp1 cpp-4.4 gcc-4.4 libstdc++6-4.4-dev g++-4.4 dhcp3-common dhcp3-client module-init-tools rsyslog upstart ubuntu-minimal initscripts libdbus-1-3 sysv-rc iptables libapparmor1 libapparmor-perl ubuntu-standard synaptic update-manager-core update-manager uuid-runtime libbluetooth3 dbus bluez bluetooth libasound2 bluez-alsa bluez-cups libgstreamer0.10-0 libgstreamer-plugins-base0.10-0 bluez-gstreamer bluez-utils libgnome-desktop-2-11 libgnome-menu2 libgnome-window-settings1 libgnomekbd-common libgnomekbd4 libgnomekbdui4 capplets-data python-gmenu gnome-menus gnome-desktop-data ubuntu-system-service gnome-control-center gnome-about libpanel-applet2-0 libwnck-common libwnck22 gnome-panel-data gnome-panel dbus-x11 gnome-session-bin gnome-session libck-connector0 consolekit devicekit-disks evolution-common evolution evolution-plugins gdebi-core gdebi gdm libgimp2.0 gimp-data gimp gnome-media-common libgnome-media0 libpulse0 libpulse-browse0 pulseaudio-utils libpulse-mainloop-glib0 gstreamer0.10-alsa gstreamer0.10-plugins-base gnome-media gstreamer0.10-tools gstreamer0.10-plugins-base-apps gstreamer0.10-x libgvfscommon0 gvfs gvfs-fuse libwbclient0 libsmbclient gvfs-backends gvfs-bin hal-info libglibmm-2.4-1c2a libpam-ck-connector libpangomm-1.4-1 libsdl1.2debian-alsa libsdl1.2debian python-gst0.10 python-software-properties samba-common smbclient winbind samba-common-bin software-properties-gtk update-motd update-notifier-common evolution-documentation-en grub-common
  │ │ └─rsyslog.postins,6279 /var/lib/dpkg/info/rsyslog.postinst configure
  │ │ └─invoke-rc.d,6471 /usr/sbin/invoke-rc.d rsyslog start
  │ │ └─rsyslog,6487 /etc/init.d/rsyslog start
  │ │ └─rsyslogd,6504 -c4
  │ │ └─rsyslogd,6505 -c4
  │ │ ├─{rsyslogd},6507
  │ │ ├─{rsyslogd},6508
  │ │ └─{rsyslogd},6642

Letting it sit for several minutes seemed to clear up the issue, and after about 5 minutes, it continued successfully. However, any start/stop actions with the init script cause the hang to happen again, but for shorter durations.

(Also, strangely, Ctrl-C and Ctrl-Z do not work in the console)

[kb (krb0+launchpad)]

This happens for every start (apt-get updated today) even after a fresh reboot, so rsyslogd is basically unusable. Attached is a gzipped strace output of the daemon when it starts. The "kernel: imklog Error return from sys_sycall: 1" write at the end loops "forever". Hopefully reverting to sysklogd is transparent...

[Michael Terry (mterry)]

The klog component of rsyslog has two modes, one reads from the kernel interface (klogctl) and one reads from /proc/kmsg (which secretly uses klogctl). klogctl will only let privileged processes read from it (well, anything that has CAP_SYS_ADMIN).

Ubuntu runs rsyslog unprivileged, but gets around this requirement by running a privileged dd instance that shovels /proc/kmsg to a location that rsyslog can read. Not pretty, but dd is relatively safe and certainly more narrow than running rsyslog with CAP_SYS_ADMIN. As a result, however, the klogctl mode doesn't really work.

The error message you are getting in your strace log is only used in klogctl mode. That mode is triggered by either the config field klogusesyscallinterface (case doesn't matter) or if the pipe /var/run/rsyslog/kmsg doesn't exist when rsyslog runs (it's created by the init script right before staring the daemon).

So... Is that config field set? Do you have any idea why /var/run/rsyslog/kmsg would not exist?

I suspect we should not respect that config field as long as we use the /proc/kmsg shoveling method.

[Michael Terry (mterry)]

Oh, wait, I can see from the strace that /var/run/rsyslog/kmsg does not exist.

[Michael Terry (mterry)]

OK, so now my question is: Do you have a customized /etc/init.d/rsyslog? If not, does running the following commands as root give you a /var/run/rsyslog/kmsg?

  mkdir -p /var/run/rsyslog
  chown syslog:syslog /var/run/rsyslog
  mkfifo -m 600 /var/run/rsyslog/kmsg
  chown syslog:syslog /var/run/rsyslog/kmsg
  start-stop-daemon --start --pidfile /var/run/rsyslog/kmsgpipe.pid --exec /bin/dd -b -m -- if=/proc/kmsg of=/var/run/rsyslog/kmsg

[Kees Cook (kees)]

My current version of rsyslog does not cause any problems, so perhaps for me, this was just an issue when upgrading.

[Michael Terry (mterry)]

Kees, depends. I updated rsyslog to not allow using the klogctl mode. If it would want to use that mode, it instead just doesn't read kernel messages.

So now, if you experienced this problem before, the symptom would be an error in /var/log/syslog like "imklog: Cannot open proc file system" and no 'kernel' messages.

[kb (krb0+launchpad)]

Mine was repeating after several reboots w/o updates over two days.

Now after a couple more days and a few "apt-get dist-upgrade"s, this no longer reproduces for me. init.d/rsyslogd seems pretty straightforward too, and the script behaves properly when removing the file unceremoniously.

This is a clean install of 9.10 server on a VM. Only thing I've done is added gcc and some build tools from the standard repos.

Perhaps this was cleaned up somewhere else.

Thanks!

Ken

[Michael Terry (mterry)]

I'm marking this Fix Released, since both kees and kb indicate it works now.

[Cezary Baginski (cezary0)]

Also had dpkg hanging on rsyslog during upgrades.

I finally removed /etc/init/rsyslog* files and purged the package.
Trying to reinstall gives me the following trace:

$sudo strace -f dpkg -i /var/cache/apt/archives/rsyslog_4.2.0-2ubuntu4_i386.deb
...
[pid 11377] socket(PF_FILE, SOCK_STREAM, 0) = 3
[pid 11377] connect(3, {sa_family=AF_FILE, path=@"/com/ubuntu/upstart"}, 22) = 0
[pid 11377] fcntl64(3, F_GETFL) = 0x2 (flags O_RDWR)
[pid 11377] fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 11377] fcntl64(3, F_GETFD) = 0
[pid 11377] fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
[pid 11377] geteuid32() = 0
[pid 11377] rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
[pid 11377] poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
[pid 11377] write(3, "\0", 1) = 1
[pid 11377] write(3, "AUTH EXTERNAL 30\r\n", 18) = 18
[pid 11377] poll([{fd=3, events=POLLIN}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
[pid 11377] read(3, "OK cdf044c963ff7a6d5ad8e06e4ac0b"..., 2048) = 37
[pid 11377] poll([{fd=3, events=POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}])
[pid 11377] write(3, "BEGIN\r\n", 7) = 7
[pid 11377] poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}])
[pid 11377] writev(3, [{"l\1\2\1\f\0\0\0\1\0\0\0_\0\0\0\1\1o\0\23\0\0\0/com/ubu"..., 112}, {"\7\0\0\0rsyslog\0", 12}], 2) = 124
[pid 11377] gettimeofday({1254313423, 131137}, NULL) = 0
[pid 11377] poll([{fd=3, events=POLLIN}], 1, 25000) = 1 ([{fd=3, revents=POLLIN}])
[pid 11377] read(3, "l\2\1\1%\0\0\0\1\0\0\0\17\0\0\0\5\1u\0\1\0\0\0\10\1g\0\1o\0\0"..., 2048) = 69
[pid 11377] read(3, 0xbfcf90, 2048) = -1 EAGAIN (Resource temporarily unavailable)
[pid 11377] writev(3, [{"l\1\2\1\10\0\0\0\2\0\0\0q\0\0\0\1\1o\0 \0\0\0/com/ubu"..., 136}, {"\0\0\0\0\1\0\0\0", 8}], 2) = 144
[pid 11377] poll([{fd=3, events=POLLIN}], 1, -1
(waits here ...)

I'll try to purge again, restart and then install to check.

[Cezary Baginski (cezary0)]

The following seems to work:
1. remove /etc/init/rsyslog* for uninstall to work
2. restart
3. install rsyslog

Now, rsyslog installs and uninstalls without problems.