Friday, November 21, 2014

Speeding up openSUSE 13.2 boot

I bought my wife a "new" old Thinkpad (T400, Core2 duo) to replace her old compaq nc6000 (Pentium M Dothan). Of course I installed it with openSUSE 13.2. Everything works fine. However, we soon found out that it takes ages to boot, something around 50 seconds, which is much more than the old machine (running 13.1 on an IDE SSD vs 13.2 on a cheap SATA SSD in the T400).
Investigating, I found out that in 13.2 the displaymanager.service is now a proper systemd service with all the correct dependencies instead of the old 13.1 xdm init script.
At home, I'm running NIS and autofs for a few NFS shares and an NTP server for the correct time.
The new displaymanager.service waits for timesetting, user account service and remote file systems, which takes lots of time.
So I did:
systemctl disable ypbind.service autofs.service ntpd.service
In order to use them anyway, I created a short NetworkManager dispatcher script which starts / stops the services "manually" if an interface goes up or down.
This brings the startup time (until the lightdm login screen appears) down to less than 11 seconds.
The next thing I found was that the machine would not shut down if an NFS mount was active. This was due to the fact that the interfaces were already shut down before the autofs service was stopped or (later) the NFS mounts were unmounted.
It is totally possible that this is caused by the violation in proper ordering I introduced by the above mentioned hack, but I did not want to go back to slow booting. So I added another hack:

  • create a small script /etc/init.d/before-halt.local which just does umount -a -t nfs -l (a lazy unmount)
  • create a systemd service file /etc/systemd/system/before-halt-local.service which is basically copied from the halt-local.service, then edited to have Before=shutdown.target instead of After=shutdown.target and to refer to the newly created before-halt.local script. Of course I could have skipped the script, but I might later need to add other stuff, so this is more convenient.
  • create the directory /etc/systemd/system/shutdown.target.wants and symlink ../before-halt-local.service into it.
And voila - before all the shutdown stuff starts, the nfs mounts are lazy unmounted and shutdown commences fast.

Hibernate Filesystem Corruption in openSUSE 13.2

UPDATE: This bug is fixed with the dracut update to version dracut-037-17.9.1

I was never very fond of dracut, but I did not think it would be so totally untested: openSUSE Bug #906592. Executive summary: hibernate will most likely silently corrupt (at least) your root filesystem during resume from disk.
If you are lucky, a later writeback from buffers / cache will "fix" it, but the way dracut resumes the system is definitely broken and I already had the filesystem corrupted on my test VM, while investigating the issue, so it is not only a theoretical problem.

Until this bug is fixed: Do not hibernate on openSUSE 13.2.

Good luck!

Thursday, November 20, 2014

pam_systemd on a server? WTF?

I noticed lots of spam in my system logs:

20141120-05:15:01.9 systemd[1]: Starting user-30.slice.
20141120-05:15:01.9 systemd[1]: Created slice user-30.slice.
20141120-05:15:01.9 systemd[1]: Starting User Manager for UID 30...
20141120-05:15:01.9 systemd[1]: Starting Session 1817 of user root.
20141120-05:15:01.9 systemd[1]: Started Session 1817 of user root.
20141120-05:15:01.9 systemd[1]: Starting Session 1816 of user wwwrun.
20141120-05:15:01.9 systemd[1]: Started Session 1816 of user wwwrun.
20141120-05:15:01.9 systemd[22292]: Starting Paths.
20141120-05:15:02.2 systemd[22292]: Reached target Paths.
20141120-05:15:02.2 systemd[22292]: Starting Timers.
20141120-05:15:02.2 systemd[22292]: Reached target Timers.
20141120-05:15:02.2 systemd[22292]: Starting Sockets.
20141120-05:15:02.2 systemd[22292]: Reached target Sockets.
20141120-05:15:02.2 systemd[22292]: Starting Basic System.
20141120-05:15:02.2 systemd[22292]: Reached target Basic System.
20141120-05:15:02.2 systemd[22292]: Starting Default.
20141120-05:15:02.2 systemd[22292]: Reached target Default.
20141120-05:15:02.2 systemd[22292]: Startup finished in 21ms.
20141120-05:15:02.2 systemd[1]: Started User Manager for UID 30.
20141120-05:15:02.2 CRON[22305]: (wwwrun) CMD (/usr/bin/php -f /srv/www/htdocs/owncloud/cron.php)
20141120-05:15:02.4 systemd[1]: Stopping User Manager for UID 30...
20141120-05:15:02.4 systemd[22292]: Stopping Default.
20141120-05:15:02.4 systemd[22292]: Stopped target Default.
20141120-05:15:02.4 systemd[22292]: Stopping Basic System.
20141120-05:15:02.4 systemd[22292]: Stopped target Basic System.
20141120-05:15:02.4 systemd[22292]: Stopping Paths.
20141120-05:15:02.4 systemd[22292]: Stopped target Paths.
20141120-05:15:02.4 systemd[22292]: Stopping Timers.
20141120-05:15:02.4 systemd[22292]: Stopped target Timers.
20141120-05:15:02.4 systemd[22292]: Stopping Sockets.
20141120-05:15:02.4 systemd[22292]: Stopped target Sockets.
20141120-05:15:02.4 systemd[22292]: Starting Shutdown.
20141120-05:15:02.4 systemd[22292]: Reached target Shutdown.
20141120-05:15:02.4 systemd[22292]: Starting Exit the Session...
20141120-05:15:02.4 systemd[22292]: Received SIGRTMIN+24 from PID 22347 (kill).
20141120-05:15:02.4 systemd[1]: Stopped User Manager for UID 30.
20141120-05:15:02.4 systemd[1]: Stopping user-30.slice.
20141120-05:15:02.4 systemd[1]: Removed slice user-30.slice.

This is a server only system. I investigated who is starting and tearing down a sytemd instance for every cronjob, every user login etc.
After some searching, I found that pam_systemd is to blame: it seems to be enabled by default. Looking into the man page of pam_systemd, I could not find anything in it that would be useful on a server system so I disabled it, and pam_gnome_keyring also while I was at it:
pam-config --delete --gnome_keyring --systemd
...and silence returned to my logfiles again.

Sunday, November 16, 2014

Is anyone still using PPP at all?

After talking to colleagues about how easy it is to contribute to the Linux Kernel simply by reporting a bug, I was actually wondering why I was the first and apparently the only one to hit this bug.
So there are two possible reasons:

  • nobody is testing -rc kernels
  • nobody is using PPP anymore
To be honest, I'm also only using PPP for some obscure VPN, but I would have expected it to be in wider usage due to UMTS/3G cards and such. So is nobody testing -rc kernels? This would indeed be bad...

Saturday, November 15, 2014

Switching from syslog-ng to rsyslog - it's easier than you might think

I had looked into rsyslog years ago, when it became default in openSUSE and for some reason I do not remember anymore, I did not really like it. So I stayed at syslog-ng.
Many people actually will not care who is taking care of their syslog messages, but since I had done a few customizations to my syslog-ng configuration, I needed to adapt those to rsyslog.

Now with Bug 899653 - "syslog-ng does not get all messages from journald, journal and syslog-ng not playing together nicely" which made it into openSUSE 13.2, I had to reconsider my choice of syslog daemon.

Basically, my customizations to syslog-ng config are pretty small:

  • log everything from VDR in a separate file "/var/log/vdr"
  • log everything from dnsmasq-dhcp in a separate file "/var/log/dnsmasq-dhcp"
  • log stuff from machines on my network (actually usually only a VOIP telephone, but sometimes some embedded boxes will send messages via syslog to my server) in "/var/log/netlog"
So I installed rsyslog -- which due to package conflicts removes syslog-ng -- and started configuring it to do the same as my old syslog-ng config had done. Important note: After changing the syslog service on your box, reboot it before doing anyting else. Otherwise you might be chasing strange problems and just rebooting is faster.

Now to the config: I did not really like the default time format of rsyslog:
2014-11-10T13:30:15.425354+01:00 susi rsyslogd: ...
Yes, I know that this is a "good" format. Easy to parse, unambiguosly, clear. But It is usually me reading the Logs and I still hate it, because I do not need microsecond precision, I do know in which timezone I'm in and it uses half of a standard terminal width if I don't scroll to the right.
So the first thing I changed was to create /etc/rsyslog.d/myformat.conf with the following content:
$template myFormat,"%timegenerated:1:4:date-rfc3339%%timegenerated:6:7:date-rfc3339%%timegenerated:9:10:date-rfc3339%-%timegenerated:12:21:date-rfc3339% %syslogtag%%msg%\n"
$ActionFileDefaultTemplate myFormat
This changes the log format to:
20141110-13:54:23.0 rsyslogd: ...
Which means the time is shorter, still can be parsed and has sub-second-precision, the hostname is gone (which might be bad for the netlog file, but I don't care) and it's 12 characters shorter.
It might be totally possible to do this in an easier fashion, I'm not a rsyslog wizard at all (yet) ;)

For /var/log/vdr and /var/log/dnsmasq-dhcp, I created the config file /etc/rsyslog.d/myprogs.conf, containing:
if $programname == 'dnsmasq-dhcp' then {
    -/var/log/dnsmasq-dhcp
    stop
}
if $programname == 'vdr' then {
    -/var/log/vdr
    stop
}
That's it! It's really straightforward, I really can't understand why I hated rsyslog years ago :)

The last thing missing was the netlog file, handled by /etc/rsyslog.d/mynet.conf:
$ModLoad imudp.so # provides UDP syslog reception
$UDPServerRun 514 # start syslog server, port 514
if $fromhost-ip startswith '192.168.' then {
    -/var/log/netlog
    stop
}
Again, pretty straightforward.
And that's it! Maybe I'll add an extra logformat for netlog to specify the hostname in there, but that would just be the icing on the cake.

What I liked especially on the rsyslog implementation in openSUSE (it might be default, but I don't know that) is, that the location of the "$IncludeConfig /etc/rsyslog.d/*.conf" is placed so that you really can do useful things without touching the distributions default config. With syslog-ng, the include of the conf.d directory was too late (for me), so you could not "split off" messages from the default definitions, e.g. the VDR messages would appear in /var/log/messages and /var/log/vdr. In order to change this, you had to change the syslog-ng.conf and this would need to be checked after a package update, and new distro-configs would need to be re-merged into my changed configuration.
Now it is totally possible that after an update of the distribution, I will need to fix my rsyslog configs because of changes in syntax or such, but at least it is possible that it might just work without that.

Monday, November 10, 2014

Home server updated to 13.2

Over the weekend, I updated my server at home from 13.1 to openSUSE 13.2.
The update was quite smooth, only a few bugs in apparently seldom used software that I needed to work around:
  • dnsmasq does not log to syslog anymore -- this is bug 904537 now
  • wwoffle did not want to start because the service file is broken, this can be fixed by adding "-d" to ExecStart and correcting the path of ExecReload to /usr/bin instead of /usr/sbin (no bugreport for that, the ExecStart is already fixed in the devel project and I submitrequested the ExecReload fix. Obviously nobody besides me is running wwwoffle, so I did not bother to bugreport)
  • The apache config needed a change from "Order allow,deny", "Allow from all" to "Require all granted", which I could find looking for changes in the default config files. Without that, I got lots of 403 "Permission denied" which are now fixed.
  • mysql (actually mariadb) needed a "touch /var/lib/mysql/.force_upgrade" before it wanted to start, but that's probably no news for people actually knowing anything about mysql (I don't, as you might have guessed already)
  • My old friend bug 899653 made it into 13.2 which means that logging from journal to syslog-ng is broken ("systemd-journal[23526]: Forwarding to syslog missed 2 messages."). Maybe it is finally time to start looking into rsyslog or plain old syslogd...
Because syslog-ng is broken for me, I needed to make the journal persistent and because journald sucks if its data is stored on rotating rust (aka HDDs), I added a separate mount point for /var/log/journal which is backed by bcache like other filesystems on that machine.

Everything seems to be running fine so far, apart from the fact that the system load was at a solid 4.0 all the time. Looking into this I found that each bcache-backed mount point had an associated kernel thread continuously in state "D". Even though this is rather cosmetic, I "fixed" it by upgrading to the latest kernel 3.17.2 from the Kernel:Stable OBS project (who wants old kernels anyway? ;)

Everything else looks good, stuff running fine:
  • owncloud
  • gallery2
  • vdr
  • NFS server
  • openvpn
Of course I have not tried everything (I eed to actually start up one of those KVM guests...), but the update has been rather painless until now.