Created attachment 983927 [details]
image1.jpg

JPG photo of screen at the time of the hang. This boot has systemd.log_level=debug enabled. This boot is the same as for journal1.txt.

Created attachment 983928 [details]
journal1.txt

'journalctl -b-1 -l -o short-monotonic' following the failed boot, so it contains the output with systemd.log_level=debug. This is the same boot for image1.txt.

Created attachment 983929 [details]
journal2.txt

rd.debug was used for this failed boot

Created attachment 983930 [details]
fedup.log

Created attachment 983931 [details]
grub.cfg

Created attachment 983932 [details]
fstab

Okay, so.. this looks like a systemd problem. Here's what I see in the log:

> upgrade-prep.sh[645]: upgrade prep complete, switching root...

So upgrade-prep.sh has finished, and systemd is executing upgrade-prep.service's
ExecStopPost command:

 ExecStopPost=-/usr/bin/systemctl --no-block isolate upgrade-switch-root.target

> systemctl[686]: Calling manager for StartUnit on upgrade-switch-root.target, isolate
> systemd[1]: Accepted new private connection.
> systemd[1]: Accepted new private connection.
> systemd-cgroups-agent[685]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/agent interface=org.freedesktop.systemd1.Agent member=Released cookie=1 reply_cookie=0 error=n/a
> systemctl[686]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 error=n/a
> systemd[1]: Got message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/agent interface=org.freedesktop.systemd1.Agent member=Released cookie=1 reply_cookie=0 error=n/a
> systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 error=n/a
> systemd[1]: SELinux access check scon=system_u:system_r:init_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=start path=/usr/lib/systemd/system/upgrade-switch-root.target cmdline=/usr/bin/systemctl --no-block isolate upgrade-switch-root.target: 0

Permissions are OK, we're now isolating upgrade-switch-root.target:

> systemd[1]: Trying to enqueue job upgrade-switch-root.target/start/isolate
> systemd[1]: Installed new job upgrade-switch-root.target/start as 214
> systemd[1]: Installed new job upgrade-switch-root.service/start as 215

Now systemd installs stop jobs for active units:

> systemd[1]: Installed new job local-fs.target/stop as 218
> [etc.]
> systemd[1]: Installed new job dm-event.socket/stop as 310

And then we actually enqueue/run upgrade-switch-root.target/start:

> systemd[1]: Enqueued job upgrade-switch-root.target/start as 214
> systemd[1]: Sent message type=method_return sender=n/a destination=n/a object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
> systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=2 reply_cookie=0 error=n/a

Something goes wrong, though:

> systemd[1]: Failed to send unit change signal for upgrade-switch-root.target: Connection reset by peer

Similarly, we fail to send signals for the rest of the jobs:

> systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=3 reply_cookie=0 error=n/a
> systemd[1]: Failed to send job change signal for 310: Transport endpoint is not connected
> [etc.]
> systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=36 reply_cookie=0 error=n/a
> systemd[1]: Failed to send job change signal for 214: Transport endpoint is not connected
> systemd[1]: Got disconnect on private connection.

Eventually stuff shuts down and we try to switch-root to the new systemd, but:

> systemd[1]: Serializing state to /run/systemd
> systemd[1]: Failed to send reloading signal: Connection reset by peer
> systemd[1]: Switching root.
> systemd[1]: Failed to send unit remove signal for sys-kernel-config.mount: Transport endpoint is not connected
> systemd[1]: Failed to send unit remove signal for local-fs.target: Transport endpoint is not connected
[etc.]

And that's where the journal ends.

My guess is that something has changed about dbus (either permissions or use of kdbus or something) between F21 and rawhide, and so either F21 systemd or rawhide systemd doesn't know how to talk to the other one properly.

Reassigning to rawhide systemd, since AFAIK F21 systemd/fedup are doing the right thing to initiate switch-root to the rawhide upgrade.img.

The messages about dbus signals don't really matter, they are shown probably mostly because a bus connection was shortliving and systemd wanted to notify it about changes, but didn't reap the connection yet. Ignore them. 

This might be an selinux issue, dunno?

Only way to figure out what is going on is by booting with the emergency shell and then stracing PID 1 over the transition or so...

Problem is the failure and subsequent forced reboot happen too quickly to attach strace; and I don't think strace is on the install media or in the initramfs either.

(In reply to Lennart Poettering from comment #8)
> This might be an selinux issue, dunno?

that'd be my guess too, but it's hard to debug over bugzilla.

> Only way to figure out what is going on is by booting with the emergency
> shell and then stracing PID 1 over the transition or so...

The fedup debug shell is enabled by default, on tty2.

(In reply to Chris Murphy from comment #9)
> Problem is the failure and subsequent forced reboot happen too quickly to
> attach strace; and I don't think strace is on the install media or in the
> initramfs either.

At the point of failure we're attempting to switch from your real root back to initramfs, so your system tools are all available.

You could edit /usr/libexec/upgrade-prep.sh and add whatever you want to happen.

Sometimes I add:

  touch /run/upgrade-wait
  while [ -f /run/upgrade-wait ]; do sleep 1; done

then use the shell on tty2 to set up debugging.

(If you're doing this in a VM, this is a good time to take a snapshot of the system.)

When you're done, "rm /run/upgrade-wait" makes the upgrade continue.

*** Bug 1190415 has been marked as a duplicate of this bug. ***

This bug appears to have been reported against 'rawhide' during the Fedora 22 development cycle.
Changing version to '22'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora22

To negate selinux issues I set enforcing=0 on the kernel command line for fedup and it still hangs with "systemd-coredump[884]: Failed to log coredump: Connection refused"

This was a freshly installed F21 Workstation VM picking default behaviour and a full yum update.

Created attachment 997869 [details]
Screenshot of hung VM

Created attachment 997871 [details]
journal output for failed fedup with selinux permissive

Created attachment 997882 [details]
'strace -fp 1' from the point of upgrade-prep.sh finishing till the final hang using the upgrade-wait trick Will described

Created attachment 997989 [details]
Realized last strace got killed when debug shell stopped. Disowned process to get fuller view of strace of pid1

It would appear from the strace systemd-216 is serializing to /var/run/systemd correctly but something is happening when systemd-219 gets switched to during the switch-root to the upgrade environment.

Unfortunately by that point whatever explodes kills the system in a sufficient way gathering logs becomes tricky (the strace attached was piped to ssh to get it off the VM and onto the parent host to minimize loss).

What is a good way to test a simple case of the systemd-216 to systemd-219 transition in a clean a way as possible to eliminate (or confirm?) that part of the upgrade process?

Created attachment 997999 [details]
coredump found in /var/lib/systemd/coredump from first fedup attempt

Created attachment 998000 [details]
coredump found in /var/lib/systemd/coredump from second fedup attempt

Created attachment 998001 [details]
coredump found in /var/lib/systemd/coredump from third fedup attempt

Created attachment 998464 [details]
screenshot of crash with systemd.log_target=kmsg systemd.log_level=debug

Lennart on the systemd-devel mailing list pointed out at the time of the switch-root the strace gets killed as part of switching root so the bit we would be interested in gets lost.

This makes it remarkably more tricky to get decent debug information.

It was requested that an attempt be made with the logs sent to the kernel buffer to avoid the journald and strace being killed prior to interesting bit issue.

As can been seen in the screenshot pid1 gets a SEGV and then execution freezes.

Created attachment 998469 [details]
switch-root at rescue.target to a yum --installroot style f22 container

Following on from the previous thought I'd check behaviour in a similar but minimal test case.

Using yum --installroot (as per the systemd-nspawn man page) created a container area.

From here used the '/usr/bin/systemctl --no-block --force switch-root /srv/mycontainer' command used by the upgrade-system-root.service in fedup to switch root into that.

The segfault can be seen more clearly than the previous example - assuming this is a valid reduced test case.

Actually I'm not entirely convinced this is a valid test case for a reduced sample in this situation ...

Doing a installroot of F21 and calling switch-root into that also fails with the same segfault.

So unless systemd-216 has a an issue (rather than the transition from 216 to 219) carrying out switch-root it could be unrelated.

But then switch-root is used for start and stop so I'd have expected to see an issue there if it was that fundamental. 

So we're still stuck at something happening in the transition between 216 and 219 after the request to switch root has occurred but with little in the way of debug due to how the processes interact during this transition.

Any further ideas on how to get some worthwhile diagnostics?

Created attachment 998543 [details]
output of fedup f21 server to f22 with systemd.log_level=debug systemd.log_target=console

This is a bit better than the screenshots ...

From virt-builder fedora-21 as a starting point fedup to TC8 server was carried out in a VM with the console directed to ttyS0 and virsh console used to connect to this.

The output of the console was copied from the terminal session directly.

Created attachment 998544 [details]
coredump from the previous fedup of f21 server linked to the console debug log output

After setting systemd.crash_shell=true and going through the standard fedup sequence I had a poke around ... the process list from the crash shell (so this is after switch-root) looks like:

sh-4.3# UID        PID  PPID CLS PRI STIME TTY          TIME CMD
root         1     0 TS   19 15:30 ?        00:00:04 /usr/lib/systemd/systemd --switched-root --system --deserialize 19
root         2     0 TS   19 15:30 ?        00:00:00 [kthreadd]
root         3     2 TS   19 15:30 ?        00:00:00 [ksoftirqd/0]
root         5     2 TS   39 15:30 ?        00:00:00 [kworker/0:0H]
root         6     2 TS   19 15:30 ?        00:00:00 [kworker/u4:0]
root         7     2 TS   19 15:30 ?        00:00:00 [rcu_sched]
root         8     2 TS   19 15:30 ?        00:00:00 [rcu_bh]
root         9     2 TS   19 15:30 ?        00:00:00 [rcuos/0]
root        10     2 TS   19 15:30 ?        00:00:00 [rcuob/0]
root        11     2 FF  139 15:30 ?        00:00:00 [migration/0]
root        12     2 FF  139 15:30 ?        00:00:00 [watchdog/0]
root        13     2 FF  139 15:30 ?        00:00:00 [watchdog/1]
root        14     2 FF  139 15:30 ?        00:00:00 [migration/1]
root        15     2 TS   19 15:30 ?        00:00:00 [ksoftirqd/1]
root        16     2 TS   19 15:30 ?        00:00:00 [kworker/1:0]
root        17     2 TS   39 15:30 ?        00:00:00 [kworker/1:0H]
root        18     2 TS   19 15:30 ?        00:00:00 [rcuos/1]
root        19     2 TS   19 15:30 ?        00:00:00 [rcuob/1]
root        20     2 TS   39 15:30 ?        00:00:00 [khelper]
root        21     2 TS   19 15:30 ?        00:00:00 [kdevtmpfs]
root        22     2 TS   39 15:30 ?        00:00:00 [netns]
root        23     2 TS   39 15:30 ?        00:00:00 [perf]
root        24     2 TS   19 15:30 ?        00:00:00 [kworker/0:1]
root        26     2 TS   39 15:30 ?        00:00:00 [writeback]
root        27     2 TS   14 15:30 ?        00:00:00 [ksmd]
root        28     2 TS    0 15:30 ?        00:00:00 [khugepaged]
root        29     2 TS   39 15:30 ?        00:00:00 [crypto]
root        30     2 TS   39 15:30 ?        00:00:00 [kintegrityd]
root        31     2 TS   39 15:30 ?        00:00:00 [bioset]
root        32     2 TS   39 15:30 ?        00:00:00 [kblockd]
root        33     2 TS   19 15:30 ?        00:00:00 [kworker/1:1]
root        34     2 TS   39 15:30 ?        00:00:00 [ata_sff]
root        36     2 TS   39 15:30 ?        00:00:00 [md]
root        37     2 TS   39 15:30 ?        00:00:00 [devfreq_wq]
root        44     2 TS   19 15:30 ?        00:00:00 [kworker/u4:1]
root        61     2 TS   19 15:30 ?        00:00:00 [kswapd0]
root        62     2 TS   19 15:30 ?        00:00:00 [fsnotify_mark]
root        72     2 TS   39 15:30 ?        00:00:00 [kthrotld]
root        73     2 TS   39 15:30 ?        00:00:00 [acpi_thermal_pm]
root        74     2 TS   19 15:30 ?        00:00:00 [scsi_eh_0]
root        75     2 TS   39 15:30 ?        00:00:00 [scsi_tmf_0]
root        76     2 TS   19 15:30 ?        00:00:00 [scsi_eh_1]
root        77     2 TS   39 15:30 ?        00:00:00 [scsi_tmf_1]
root        79     2 TS   39 15:30 ?        00:00:00 [kpsmoused]
root        80     2 TS   39 15:30 ?        00:00:00 [dm_bufio_cache]
root        82     2 TS   39 15:30 ?        00:00:00 [ipv6_addrconf]
root        84     2 TS   39 15:30 ?        00:00:00 [deferwq]
root       118     2 TS   39 15:30 ?        00:00:00 [kmpathd]
root       119     2 TS   39 15:30 ?        00:00:00 [kmpath_handlerd]
root       133     2 TS   19 15:30 ?        00:00:00 [kauditd]
root       266     2 TS   39 15:30 ?        00:00:00 [rpciod]
root       296     2 TS   39 15:30 ?        00:00:00 [kmpath_rdacd]
root       328     2 TS   19 15:30 ?        00:00:00 [kworker/0:3]
root       402     1 TS   19 15:30 ?        00:00:05 @usr/sbin/plymouthd --mode=boot --pid-file=/var/run/plymouth/pid --attach-to-session
root       430     2 TS   39 15:30 ?        00:00:00 [ttm_swap]
root       431     2 TS   39 15:30 ?        00:00:00 [qxl_gc]
root       448     2 TS   39 15:30 ?        00:00:00 [kworker/1:1H]
root       455     2 TS   19 15:30 ?        00:00:00 [jbd2/vda3-8]
root       456     2 TS   39 15:30 ?        00:00:00 [ext4-rsv-conver]
root       569     1 TS   19 15:31 ?        00:00:00 [systemd-journal] <defunct>
root       626     2 TS   39 15:31 ?        00:00:00 [kworker/0:1H]
root       657     2 TS   19 15:31 ?        00:00:00 [jbd2/vda1-8]
root       658     2 TS   39 15:31 ?        00:00:00 [ext4-rsv-conver]
root       710     1 TS   19 15:31 ?        00:00:00 [systemctl] <defunct>
root       723     1 TS   19 15:32 ?        00:00:00 /bin/sh

Based on the output of mount it doesn't appear that the root switch completes with the failure happening after that:

sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime,seclabel)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
devtmpfs on /dev type devtmpfs (rw,nosuid,seclabel,size=1002552k,nr_inodes=250638,mode=755)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,seclabel)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,seclabel,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,nodev,seclabel,mode=755)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,seclabel,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/usr/lib/systemd/systemd-cgroups-agent,name=systemd)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime,seclabel)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
configfs on /sys/kernel/config type configfs (rw,relatime)
/dev/vda3 on / type ext4 (rw,relatime,seclabel,data=ordered)
tmpfs on /system-upgrade-root type tmpfs (rw,relatime,seclabel,mode=755)
selinuxfs on /sys/fs/selinux type selinuxfs (rw,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,relatime,seclabel)
mqueue on /dev/mqueue type mqueue (rw,relatime,seclabel)
tmpfs on /tmp type tmpfs (rw,seclabel)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime,seclabel)
/dev/vda3 on /system-upgrade-root/sysroot type ext4 (rw,relatime,seclabel,data=ordered)
devtmpfs on /system-upgrade-root/sysroot/dev type devtmpfs (rw,nosuid,seclabel,size=1002552k,nr_inodes=250638,mode=755)
tmpfs on /system-upgrade-root/sysroot/dev/shm type tmpfs (rw,nosuid,nodev,seclabel)
devpts on /system-upgrade-root/sysroot/dev/pts type devpts (rw,nosuid,noexec,relatime,seclabel,gid=5,mode=620,ptmxmode=000)
mqueue on /system-upgrade-root/sysroot/dev/mqueue type mqueue (rw,relatime,seclabel)
hugetlbfs on /system-upgrade-root/sysroot/dev/hugepages type hugetlbfs (rw,relatime,seclabel)
proc on /system-upgrade-root/sysroot/proc type proc (rw,nosuid,nodev,noexec,relatime)
systemd-1 on /system-upgrade-root/sysroot/proc/sys/fs/binfmt_misc type autofs (rw,rsysfs on /system-upgrade-root/sysroot/sys type sysfs (rw,nosuid,nodev,noexec,relatime,seclabel)
securityfs on /system-upgrade-root/sysroot/sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /system-upgrade-root/sysroot/sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,seclabel,mode=755)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/usr/lib/systemd/systemd-cgroups-agent,name=systemd)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /system-upgrade-root/sysroot/sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
pstore on /system-upgrade-root/sysroot/sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime,seclabel)
configfs on /system-upgrade-root/sysroot/sys/kernel/config type configfs (rw,relatime)
selinuxfs on /system-upgrade-root/sysroot/sys/fs/selinux type selinuxfs (rw,relatime)
debugfs on /system-upgrade-root/sysroot/sys/kernel/debug type debugfs (rw,relatime,seclabel)
tmpfs on /system-upgrade-root/sysroot/run type tmpfs (rw,nosuid,nodev,seclabel,mode=755)
tmpfs on /system-upgrade-root/sysroot/tmp type tmpfs (rw,seclabel)
/dev/vda1 on /system-upgrade-root/sysroot/boot type ext4 (rw,relatime,seclabel,data=ordered)

Given the pid count and the fact the switch-root appears to have failed I'm guessing the systemd that actually segfaulted was the new systemd-219 version given the state of pid 1 in the process list above.

This is very reproducible with very simple steps ... 

1. virt-builder fedora-21 --update --install fedup,strace
2. start image virt virsh/kvm/etc
3. in guest fedup --network 22 --instrepo=https://path/to/instrepo/os/ --nogpgcheck
4. Edit grub.cfg to append systemd.log_level=debug systemd.log_target=console systemd.chrash_shell=true enforcing=0
5. connect via virsh console to see console output
6. reboot and watch fedup fail with the segfault and coredump

What is the best way to find out why systemd-219 in the fedup environment is segfaulting and failing to start and be switched to correctly?

(In reply to James Hogarth from comment #27)
> Given the pid count and the fact the switch-root appears to have failed I'm
> guessing the systemd that actually segfaulted was the new systemd-219
> version given the state of pid 1 in the process list above.

No, if you use crash_shell then systemd forks /bin/bash and then just goes into an infinite sleep. So it makes sense that PID 1 is still "alive".

Also, most importantly, the core file from comment #26 is for systemd-216, not systemd-219.

(You could probably verify this by checking `ls -i /proc/1/maps` before the switch-root and after the crash. If the inode number has changed, systemd re-exec'd itself.)

I'm attaching a full backtrace for the coredump in comment #26, but the short version is this:

Core was generated by `/usr/lib/systemd/systemd --switched-root --system --deserialize 22'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f4a008ddf99 in raise () from /lib64/libpthread.so.0
#0  0x00007f4a008ddf99 in raise () from /lib64/libpthread.so.0
#1  0x00007f4a01e608f8 in crash.lto_priv.223 (sig=11) at ../src/core/main.c:168
#2  <signal handler called>
#3  0x00007f4a006584e0 in __strcmp_ssse3 () from /lib64/libc.so.6
#4  0x00007f4a01984be5 in selabel_sub () from /lib64/libselinux.so.1
#5  0x00007f4a01984d30 in selabel_lookup_common () from /lib64/libselinux.so.1
#6  0x00007f4a0198511b in selabel_lookup_raw () from /lib64/libselinux.so.1
#7  0x00007f4a01e6322f in mac_selinux_create_file_prepare (path=path@entry=0x7ffd2b2e9aa0 "/system-upgrade-root/mnt", mode=mode@entry=16384) at ../src/shared/selinux-util.c:320
#8  0x00007f4a01e6358a in mkdir_label (path=0x7ffd2b2e9aa0 "/system-upgrade-root/mnt", mode=493) at ../src/shared/label.c:44
#9  0x00007f4a01e63625 in mkdir_p_internal (prefix=0x0, _mkdir=0x7f4a01e63570 <mkdir_label>, mode=493, path=0x7ffd2b2e9aa0 "/system-upgrade-root/mnt") at ../src/shared/mkdir.c:123
#10 mkdir_p_label (path=path@entry=0x7ffd2b2e9aa0 "/system-upgrade-root/mnt", mode=mode@entry=493) at ../src/shared/mkdir-label.c:44
#11 0x00007f4a01e83387 in switch_root.constprop.199 (new_root=0x7f4a02cb75e0 "/system-upgrade-root", mountflags=8192, detach_oldroot=true, oldroot=0x7f4a01ebb97b "/mnt") at ../src/shared/switch-root.c:56
#12 0x00007f4a01ddc2fb in main (argc=5, argv=<optimized out>) at ../src/core/main.c:1889

So - it looks like switch_root() tries to mkdir_p_label("/system-upgrade-root/mnt"), but the attempt to look up the correct SELinux label for that directory causes a SEGV.

This probably doesn't happen in the normal initramfs-to-system switch-root because we don't have SELinux policy loaded at that point.

This also would explain why you can reproduce the problem with a F21-to-F21 switch-root.

Created attachment 999004 [details]
Full backtrace of coredump from comment #26

Generated with `gdb --core=core.systemd.* --batch -ex 'bt full'`

(In reply to Will Woods from comment #28)

> So - it looks like switch_root() tries to
> mkdir_p_label("/system-upgrade-root/mnt"), but the attempt to look up the
> correct SELinux label for that directory causes a SEGV.
> 
> This probably doesn't happen in the normal initramfs-to-system switch-root
> because we don't have SELinux policy loaded at that point.
> 
> This also would explain why you can reproduce the problem with a F21-to-F21
> switch-root.

Thanks for that analysis of the coredump Will...

Interesting my testing was with enforcing=0 passed to the fedup kernel and it still blew up.

I'll give it a go with SELinux completely disabled and see how it behaves and try to work backwards from there.

So configuring the test system as permissive (and enforcing=0) incurs the crash as previously mentioned.

Running a test upgrade with the test system disabled and selinux=0 the upgrade happens mostly as expected.

It hung at the end after reboot target when it failed to unmount /sysroot:

About to execute: /bin/umount /sysroot -n
systemd-journald.service: Got notification message from PID 11735 (FDSTORE=1)
systemd-journald.service: got FDSTORE=1
systemd-journald.service: added fd to fd store.
Got disconnect on private connection.
Received SIGCHLD from PID 11742 (umount).
Child 11742 (umount) died (code=exited, status=32/n/a)
Child 11742 belongs to sysroot.mount
sysroot.mount mount process exited, code=exited status=32
sysroot.mount changed unmounting -> mounted
Job sysroot.mount/stop finished, result=failed

Forcing a restart of the VM started F22 as expected and booting after a relabel and setting selinux back to enforcing works.

Will the corefile being 216 doesn't seem to line up with that stacktrace you've pulled out...

It refers to src/shared/switch-root.c and the mkdir_p_label indeed but that's in 219:

https://github.com/systemd/systemd/blob/v219/src/shared/switch-root.c

In 216 switch-root was carried out at src/core/switch-root.c and used mkdir_p not mkdir_p_label:

https://github.com/systemd/systemd/blob/v216/src/core/switch-root.c

I'm popping some waits in the various upgrade shell scripts at the appropriate points to try and nail down exactly what is failing where...

It does start to look like the selinux policy database may need an update before fedup works for some reason though ... or systemd needs to handle the lack of label in the policy database for /system-upgrade-root/mnt used for the temporary pivot in a better way than a segfault somehow ;)

Ah my mistake there ...

Although it's systemd-216 in F21 by the RPM version I just grabbed the SRPM and it's on the 217 (plus patches) codebase... nice and confusing ;)

And indeed 217 is when switch-root was moved from core to shared:

https://github.com/systemd/systemd/blob/v217/src/shared/switch-root.c

And indeed it is carrying out the mkdir_p_label there ...

So it looks like this is the first time we're doing a switch-root with mkdir_p_label and with policy in place (since as you mentioned policy isn't loaded in the fedup initrd environment).

So either looking to sort out the policy issues or handling this edge case better should resolve the behaviour.

Created attachment 999038 [details]
backtrace with ssse3 disabled in the VM

So as a long shot somewhat given the previous backtrace I disabled SSSE3 in the VM and tried the upgrade. 

It failed with a similar backtrace (attached) with the strcmp in selabel_sub appearing to the the initial point of failure that then bubbles up the chain.

I'm inclined to think at this point it's not a systemd issue in and of itself but rather the change of mkdir_p to mkdir_p_label used by switch-root.c in the systemd-217 version in F21 has highlighted some underlying issue in libselinux since the labelling is now checked.

At any rate the actual initial failure appears to be in libselinux with the rest bubbling out from there...

For now a workaround of disabling selinux, carrying out the fedup process, enabling selinux and relabelling the filesystem appears to work to test the upgrade itself.

I'd suggest this gets reassigned to libselinux for the maintainers in that area to take a look.

I'm trying to put together a minimal test case of the same code path but annoyingly this *doesn't* fail like systemd does:

#include <stdio.h>
#include <stdlib.h>
#include <errno.h>
#include <selinux/label.h>
#include <sys/stat.h>

int main(int argc, char *argv[])  {
  char *path;
  int r;
  security_context_t filecon = NULL;
  static struct selabel_handle *label_hnd = NULL;

  path = argv[1];
  label_hnd = selabel_open(SELABEL_CTX_FILE, NULL, 0);

  freecon(filecon);


  r = selabel_lookup_raw(label_hnd, &filecon, path, S_IFDIR);

  if (r < 0 && errno == ENOENT) {
    r = 0;
    return 0;
  }
  if (r < 0) {
    r = -errno;
  }

  printf("%s\n", filecon);

return 0;
}

The function selabel_lookup_raw (which is the one called by mac_selinux_create_file_prepare in src/shared/selinux-util.c from mkdir_label) works fine in this minimal test case which I've tried to get reflecting the real one... 

Tested in both the fedup environment just before switch-root and just local in F21 ...

Starting to run out of ideas here.

(In reply to James Hogarth from comment #31)
> So configuring the test system as permissive (and enforcing=0) incurs the
> crash as previously mentioned.

Yes. We still look up (and apply) labels in permissive mode. The system just doesn't enforce the rules.

> Running a test upgrade with the test system disabled and selinux=0 the
> upgrade happens mostly as expected.

Which makes sense because we don't have any policy to look up labels in.

> It hung at the end after reboot target when it failed to unmount /sysroot:
>
> [...]
> 
> Forcing a restart of the VM started F22 as expected and booting after a
> relabel and setting selinux back to enforcing works.

Unrelated; please file that in a separate bug if you want to track that.

(In reply to James Hogarth from comment #32)
> It does start to look like the selinux policy database may need an update
> before fedup works for some reason though ... or systemd needs to handle the
> lack of label in the policy database for /system-upgrade-root/mnt used for
> the temporary pivot in a better way than a segfault somehow ;)

Maybe the lookup is happening using the on-disk policy (which is F21's) but the *loaded* policy is F22s? I'm having trouble remembering the gritty details of how labels get loaded and applied, but I'd thought they got pulled out of the in-memory policy..

*** Bug 1199849 has been marked as a duplicate of this bug. ***

*** Bug 1200880 has been marked as a duplicate of this bug. ***

Created attachment 1000710 [details]
Full backtrace with correct libselinux debuginfo

So here's an improved backtrace of that coredump, with with the correct libselinux debuginfo installed.

The proximal cause of the SEGV is that there's garbage in systemd's selinux labeling handle (label_hnd) - specifically, in label_hnd->dist_subs.

libselinux reads /etc/selinux/targeted/contexts/files/file_contexts.subs_dist
into the dist_subs linked list when you do selabel_open(SELABEL_CTX_FILE, ..).

Normally that list looks like this:

  {src[]="/var/roothome", slen=13, dst[]="/root", next=<ptr>}
  {src[]="/var/home",     slen=9,  dst[]="/home", next=<ptr>}
  ...12 more items...
  {src[]="/run",          slen=4,  dst[]="/var/run", next=NULL}

In the coredump, the dist_subs items look like this:

  {src[]="`",        slen=13, dst[]=" \222\253\002J\177", next=<ptr>}
  {src[]="\300\005", slen=9,  dst[]="\260\221\253\002J\177", next=<ptr>}
  ...10 more items...
  {src[]="\340",     slen=19, dst[]="Ќ\253\002J\177", next=<ptr>}

So: garbage data in src and dest, but the slen values are normal.. The item after this one, the 'next' pointer points back into itself(??), and then we get a garbage item that has src=0x0, which makes strncmp SEGV.

I think this turns out to be a use-after-free bug in F21 systemd (v216).

When systemd v216 shuts down, it does label_finish() before switch_root():
  https://github.com/systemd/systemd/blob/v216/src/core/main.c#L1819-1845

But label_finish() doesn't set label_hnd=NULL:
  https://github.com/systemd/systemd/blob/v216/src/shared/label.c#L205

So mkdir_p_label() ends up using the freed label_hnd (which now contains a bunch of garbage), leading to the segfault.

In master that function is named mac_selinux_finish(), but it has the same bug:
  https://github.com/systemd/systemd/blob/master/src/shared/selinux-util.c#L118

I'm building a systemd to test the following fix:

diff --git a/src/shared/label.c b/src/shared/label.c
index 25a8b36..ecce6aa 100644
--- a/src/shared/label.c
+++ b/src/shared/label.c
@@ -203,6 +203,8 @@ void label_finish(void) {
 
         if (label_hnd)
                 selabel_close(label_hnd);
+
+        label_hnd = NULL;
 #endif
 }

Created attachment 1001497 [details]
0001-Fix-SEGV-during-switch-root-from-system-with-SELinux.patch

Confirmed - the attached patch fixes the segfault. Test system is happily upgrading to F22 Alpha.

Patch is against systemd master but applies to F21 systemd just fine.

A scratch build should be available from koji soon:
  http://koji.fedoraproject.org/koji/taskinfo?taskID=9226067

I'll send the patch to the systemd-devel mailing list shortly.

+1 for the patch / scratch build. Issue reproduced and fix confirmed.

systemd-219-9.fc22 has been submitted as an update for Fedora 22.
https://admin.fedoraproject.org/updates/systemd-219-9.fc22

Package systemd-219-9.fc22:
* should fix your issue,
* was pushed to the Fedora 22 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing systemd-219-9.fc22'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2015-3949/systemd-219-9.fc22
then log in and leave karma (feedback).

...that update won't fix the bug, though.

The actual bug is in F21 systemd (v216). It will SEGV any time you attempt to switch-root when SELinux policy has been loaded. (It just happens to be the case that fedup is the only thing that does this on a regular basis.)

This will require a F21 update to fix. (And I should probably make F21 fedup Require: the new systemd version.)

To clarify - yes, the actual systemd bug needs fixing in both F21 and F22.
It's now fixed in F22, and upstream git:
  http://cgit.freedesktop.org/systemd/systemd/commit/?id=f5ce2b4
but *this* report concerns the failure to upgrade from F21 - so closing this bug requires a patch to F21 systemd.

(And probably I should make fedup Require the new systemd version, when that appears..)

Yes, I know. I just didn't get to making the F21 update yet.

No worries - just want to be sure everyone's clear! (There's been a lot of confusion about where the crash actually happened, etc.)

(In reply to Will Woods from comment #45)
> The actual bug is in F21 systemd (v216).

Is the bug also in systemd-208-31.fc20, or in systemd-204-21.fc19? Officially we support F20->F22 upgrades. And I think we'd like to offer F19->F22 upgrades even though F19 isn't supported anymore.

AFAICT no; the bug was introduced in this commit, which (as part of a refactor) replaced mkdir_p() with mkdir_p_label() in switch_root():

  http://cgit.freedesktop.org/systemd/systemd-stable/commit/?h=v216-stable&id=5a4bf02

So it should only be present in v216-stable/v217 and later systemd.

(Also, since what you're upgrading *to* is mostly irrelevant, if the bug was present in F19/F20 we would have hit this on upgrades to F20/F21..)

Is it still planned to be solved? IMHO, this is one of the most serious bugs, since it ruins the entire QA idea.

Mykola: https://bugzilla.redhat.com/show_bug.cgi?id=1185604#c47

systemd-219-9.fc22 has been pushed to the Fedora 22 stable repository.  If problems still persist, please make note of it in this bug report.

As discussed above the F22 update does not fix this. Re-opening.

systemd-216-23.fc21 has been submitted as an update for Fedora 21.
https://admin.fedoraproject.org/updates/systemd-216-23.fc21

Package systemd-216-24.fc21:
* should fix your issue,
* was pushed to the Fedora 21 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing systemd-216-24.fc21'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2015-4991/systemd-216-24.fc21
then log in and leave karma (feedback).

The fix for this has been verified by multiple testers, and is only awaiting a stable push.

systemd-216-24.fc21 has been pushed to the Fedora 21 stable repository.  If problems still persist, please make note of it in this bug report.