systemd segfault

[edevil]

Issue Report

Bug

Systemd crashes frequently on a number of Kubernetes nodes that run CoreOS.

CoreOS Version

NAME=CoreOS
ID=coreos
VERSION=1122.2.0
VERSION_ID=1122.2.0
BUILD_ID=2016-09-06-1449
PRETTY_NAME="CoreOS 1122.2.0 (MoreOS)"
ANSI_COLOR="1;32"
HOME_URL="https://coreos.com/"
BUG_REPORT_URL="https://github.com/coreos/bugs/issues"

Environment

Azure VM

Expected Behavior

Systemd should not crash.

Actual Behavior

Dec 03 03:29:42 node-4-vm kernel: show_signal_msg: 15 callbacks suppressed
Dec 03 03:29:42 node-4-vm kernel: systemd[1]: segfault at 7ff58fe25d13 ip 00007ff593697cf6 sp 00007ffe8bb9fa90 error 4 in libpthread-2.21.so[7ff593690000+18000]

Dec 04 09:01:23 node-0-vm kernel: show_signal_msg: 18 callbacks suppressed
Dec 04 09:01:23 node-0-vm kernel: systemd[1]: segfault at 7f1b581d3d13 ip 00007f1b5c246cf6 sp 00007ffc123bec00 error 4 in libpthread-2.21.so[7f1b5c23f000+18000]

Reproduction Steps

1. Leave the machines running for a few days
2. After a while we stop being able to SSH into them. The connection opens but no sshd banner appears.

[crawford]

Does this segfault still happen on the latest Stable release? Can you provide the coredump?

[edevil]

I turned off the auto upgrades because I ran into some bugs, but has anything related to this been fixed since then?

Where are coredumps stored in CoreOS?

[edevil]

It seems there's no coredump:

# coredumpctl info
No coredumps found.

[crawford]

I turned off the auto upgrades because I ran into some bugs, but has anything related to this been fixed since then?

It's tough to tell since there is no coredump. A number of things have changed, so it's likely that something along the way addresses this failure.

[edevil]

I got another crash and this time a coredump was produced:

[132045.964325] systemd[1]: segfault at 7f185cbdad13 ip 00007f1860d80cf6 sp 00007ffe7489b020 error 4 in libpthread-2.21.so[7f1860d79000+18000]
[132046.357293] systemd-coredump[44943]: Due to PID 1 having crashed coredump collection will now be turned off.
[132051.614055] systemd-coredump[44943]: Detected coredump of the journal daemon or PID 1, diverted to /var/lib/systemd/coredump/core.systemd.0.24e4c5a7f3b642bbaadd512bbdea41d7.44942.1481152329000000.xz.

core.zip

Needless to say, having your PID 1 crash AND losing the ability to SSH into your machine because for some reason systemd is now handling the 22 port is a bad way to start your day. :)

Also, I ran the update yesterday and could swear that I had upgraded to the latest stable (1185.3.0):

Dec 06 10:27:24 node-4-vm update_engine[36087]: [1206/102724:INFO:libcurl_http_fetcher.cc(240)] HTTP response code: 200
Dec 06 10:27:24 node-4-vm update_engine[36087]: [1206/102724:INFO:libcurl_http_fetcher.cc(297)] Transfer completed (200), 767 bytes downloaded
Dec 06 10:27:24 node-4-vm update_engine[36087]: [1206/102724:INFO:omaha_request_action.cc(574)] Omaha request response: <?xml version="1.0" encoding="U
Dec 06 10:27:24 node-4-vm update_engine[36087]: <response protocol="3.0" server="update.core-os.net">
Dec 06 10:27:24 node-4-vm update_engine[36087]:  <daystart elapsed_seconds="0"></daystart>
Dec 06 10:27:24 node-4-vm update_engine[36087]:  <app appid="e96281a6-d1af-4bde-9a0a-97b76e56dc57" status="ok">
Dec 06 10:27:24 node-4-vm update_engine[36087]:   <updatecheck status="ok">
Dec 06 10:27:24 node-4-vm update_engine[36087]:    <urls>
Dec 06 10:27:24 node-4-vm update_engine[36087]:     <url codebase="https://update.release.core-os.net/amd64-usr/1185.3.0/"></url>
...
ec 06 10:27:24 node-4-vm update_engine[36087]: [1206/102724:INFO:update_attempter.cc(309)] Update successfully applied, waiting to reboot.
Dec 06 10:27:24 node-4-vm update_engine[36087]: [1206/102724:INFO:update_check_scheduler.cc(82)] Next update check in 40m23s
...
-- Reboot --
Dec 07 03:43:46 localhost systemd-journald[170]: Runtime journal (/run/log/journal/) is 8.0M, max 83.9M, 75.9M free.
Dec 07 03:43:46 localhost kernel: Linux version 4.7.3-coreos-r2 (jenkins@jenkins-os-executor-1.c.coreos-gce-testing.internal) (gcc version 4.9.3 (Gento
Dec 07 03:43:46 localhost kernel: Command line: BOOT_IMAGE=/coreos/vmlinuz-b mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c rootflags=rw mount
Dec 07 03:43:46 localhost kernel: x86/fpu: Legacy x87 FPU detected.

However I rebooted the machine because of the crash and it shows version 1122.2.0. Can it have reverted because of the crash?

[edevil]

Can I provide additional help in debugging this issue? Should I file an issue with systemd?

[crawford]

Can it have reverted because of the crash?

Potentially. The boot isn't marked "good" until a few minutes after it's running (update-engine.service is the one that will actually mark it). So if this machine rebooted before it could be marked good, it would have gone back to the previous version.

[edevil]

@crawford Where can I find debug symbols for the systemd binary? I'm very much interested in helping debug this problem.

[crawford]

We split them when we build the OS. Unfortunately, they are not published at the moment, but we will be changing that. I tried your coredump against the debug symbols I generated, but GDB wasn't able to associate function names to the items in the backtrace. Either the stack was smashed or there is something wrong with the symbols I generated (I'm double checking that now).

[edevil]

Which CoreOS version are you using? Do all 1185.x point releases use the same systemd binary? I'm almost positive I was not on 1122 at the time but you never know.

[crawford]

As my co-worker pointed out, the stack is clearly messed up:

(gdb) bt
#0  0x00007f18609fda47 in ?? ()
#1  0x0000563a676c43a4 in ?? ()
#2  0x733d656d616e3a31 in ?? ()
#3  0x2f00646d65747379 in ?? ()
#4  0xffffffffffffffff in ?? ()
#5  0xffffffffffffffff in ?? ()
#6  0x00007ffe7489b030 in ?? ()
#7  0x00007f1860a13264 in ?? ()
#8  0x0000000000000006 in ?? ()
#9  0x00007ffe7489abc0 in ?? ()
#10 0x00007f18624c26e8 in ?? ()
#11 0x0000000000000000 in ?? ()

Could you try reproducing the failure on Beta or Alpha? That has systemd 231, which will go to Stable in a few weeks.

[edevil]

CoreOS 1185 already has systemd 231:

$ /usr/lib/systemd/systemd --version
systemd 231
+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN

I don't have other environments where I can try Beta or Alpha versions... Is there some logging that I can increase to help pinpoint the problem? How do I alter systemd's command line flags?

[crawford]

Oh yes, ha. Could you try the current Stable and see if you are able to reproduce the failure? If you see the failure again, we can look into increasing the log level.

[edevil]

The latest crash I had, the one which produced the core file, was with 1185.3.0. I don't see any systemd related changes comparing with the latest stable 1185.5.0. It was only after I rebooted the machine that it went back to 1122. The fact that I have disabled the update service had probably something to do with this.

[crawford]

I see. I thought that coredump was from an older version of systemd. Either way, that stack has been corrupted.

To increase the logging verbosity of system, you can add the following to /etc/systemd/system.conf:

LogLevel=debug

[edevil]

I managed to catch a debug log of systemd crashing. This is a system running 1122.2.0, so systemd 229, but the crash seems similar when I upgrade to 231.

Dec 16 08:15:27 node-2-vm sshd[43029]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm sshd[43022]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: Incoming traffic
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174507-10.0.3.12:22-168.63.129.16:49237.service: Trying to enqueue job sshd@174507-10.0.3.12:22-168.63.129.16:49237.service/start/replace
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174507-10.0.3.12:22-168.63.129.16:49237.service: Installed new job sshd@174507-10.0.3.12:22-168.63.129.16:49237.service/start as 12916113
Dec 16 08:15:27 node-2-vm sshd[43021]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm sshd[43028]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174507-10.0.3.12:22-168.63.129.16:49237.service: Enqueued job sshd@174507-10.0.3.12:22-168.63.129.16:49237.service/start as 12916113
Dec 16 08:15:27 node-2-vm sshd[43024]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm sshd[43030]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm sshd[43027]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400596 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm kernel: show_signal_msg: 27 callbacks suppressed
Dec 16 08:15:27 node-2-vm sshd[43025]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm sshd[43023]: Did not receive identification string from 168.63.129.16
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400597 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=1400598 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=1400599 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: Incoming traffic
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174508-10.0.3.12:22-168.63.129.16:49238.service: Trying to enqueue job sshd@174508-10.0.3.12:22-168.63.129.16:49238.service/start/replace
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174508-10.0.3.12:22-168.63.129.16:49238.service: Installed new job sshd@174508-10.0.3.12:22-168.63.129.16:49238.service/start as 12916187
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174508-10.0.3.12:22-168.63.129.16:49238.service: Enqueued job sshd@174508-10.0.3.12:22-168.63.129.16:49238.service/start as 12916187
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400600 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400601 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=1400602 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=1400603 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Received SIGCHLD from PID 43028 (sshd).
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43028 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174497-10.0.3.12:22-168.63.129.16:65423.service: Child 43028 belongs to sshd@174497-10.0.3.12:22-168.63.129.16:65423.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174497-10.0.3.12:22-168.63.129.16:65423.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 13 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174497-10.0.3.12:22-168.63.129.16:65423.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174497-10.0.3.12:22-168.63.129.16:65423.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174497-10.0.3.12:22-168.63.129.16:65423.service: Collecting.
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=1400604 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: Incoming traffic
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174509-10.0.3.12:22-168.63.129.16:49240.service: Trying to enqueue job sshd@174509-10.0.3.12:22-168.63.129.16:49240.service/start/replace
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174509-10.0.3.12:22-168.63.129.16:49240.service: Installed new job sshd@174509-10.0.3.12:22-168.63.129.16:49240.service/start as 12916261
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174509-10.0.3.12:22-168.63.129.16:49240.service: Enqueued job sshd@174509-10.0.3.12:22-168.63.129.16:49240.service/start as 12916261
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400605 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sshd_2esocket interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1400606 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=1400607 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=1400608 reply_cookie=0 error=n/a
Dec 16 08:15:27 node-2-vm systemd[1]: Received SIGCHLD from PID 43027 (sshd).
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43027 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174498-10.0.3.12:22-168.63.129.16:65424.service: Child 43027 belongs to sshd@174498-10.0.3.12:22-168.63.129.16:65424.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174498-10.0.3.12:22-168.63.129.16:65424.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 13 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174498-10.0.3.12:22-168.63.129.16:65424.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174498-10.0.3.12:22-168.63.129.16:65424.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43021 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174503-10.0.3.12:22-168.63.129.16:65429.service: Child 43021 belongs to sshd@174503-10.0.3.12:22-168.63.129.16:65429.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174503-10.0.3.12:22-168.63.129.16:65429.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 12 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174503-10.0.3.12:22-168.63.129.16:65429.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174503-10.0.3.12:22-168.63.129.16:65429.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43022 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174502-10.0.3.12:22-168.63.129.16:65425.service: Child 43022 belongs to sshd@174502-10.0.3.12:22-168.63.129.16:65425.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174502-10.0.3.12:22-168.63.129.16:65425.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 11 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174502-10.0.3.12:22-168.63.129.16:65425.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174502-10.0.3.12:22-168.63.129.16:65425.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43023 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174501-10.0.3.12:22-168.63.129.16:65428.service: Child 43023 belongs to sshd@174501-10.0.3.12:22-168.63.129.16:65428.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174501-10.0.3.12:22-168.63.129.16:65428.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 10 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174501-10.0.3.12:22-168.63.129.16:65428.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174501-10.0.3.12:22-168.63.129.16:65428.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43024 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174500-10.0.3.12:22-168.63.129.16:65426.service: Child 43024 belongs to sshd@174500-10.0.3.12:22-168.63.129.16:65426.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174500-10.0.3.12:22-168.63.129.16:65426.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 9 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174500-10.0.3.12:22-168.63.129.16:65426.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174500-10.0.3.12:22-168.63.129.16:65426.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43025 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174499-10.0.3.12:22-168.63.129.16:65427.service: Child 43025 belongs to sshd@174499-10.0.3.12:22-168.63.129.16:65427.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174499-10.0.3.12:22-168.63.129.16:65427.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 8 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174499-10.0.3.12:22-168.63.129.16:65427.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174499-10.0.3.12:22-168.63.129.16:65427.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43029 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174496-10.0.3.12:22-168.63.129.16:65422.service: Child 43029 belongs to sshd@174496-10.0.3.12:22-168.63.129.16:65422.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174496-10.0.3.12:22-168.63.129.16:65422.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm systemd[1]: sshd.socket: One connection closed, 7 left.
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174496-10.0.3.12:22-168.63.129.16:65422.service: Changed running -> dead
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174496-10.0.3.12:22-168.63.129.16:65422.service: cgroup is empty
Dec 16 08:15:27 node-2-vm systemd[1]: Child 43030 (sshd) died (code=exited, status=255/n/a)
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174495-10.0.3.12:22-168.63.129.16:65421.service: Child 43030 belongs to sshd@174495-10.0.3.12:22-168.63.129.16:65421.service
Dec 16 08:15:27 node-2-vm systemd[1]: sshd@174495-10.0.3.12:22-168.63.129.16:65421.service: Main process exited, code=exited, status=255/n/a
Dec 16 08:15:27 node-2-vm kernel: systemd[1]: segfault at 7f600cdf4d13 ip 00007f6010e67cf6 sp 00007ffda37965c0 error 4 in libpthread-2.21.so[7f6010e60000+18000]

[edevil]

Relevant systemd issue: systemd/systemd#4869

[edevil]

According to the systemd folk, and I'm inclined to agree, I'm hitting this glibc 2.21 regression. There seems to be a patch but it has not been merged. Can CoreOS include it since upstream seems unable to?

[dm0-]

The glibc patch should be in the alpha tomorrow.