Bug 87428

Summary: systemd-nspawn: restarting systemd-nspawn@ container fails
Product: systemd Reporter: Jonathan Liu <net147>
Component: generalAssignee: systemd-bugs
Status: RESOLVED FIXED QA Contact: systemd-bugs
Severity: major    
Priority: medium CC: lennart
Version: unspecified   
Hardware: x86-64 (AMD64)   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Attachments: systemd v219 debug log - start and reboot nspawn container

Description Jonathan Liu 2014-12-18 01:05:52 UTC 
Using systemd 218 from [testing] repository on Arch Linux x86_64.

# mkdir /var/lib/container/test
# pacstrap -i -c -d /var/lib/container/test base
# systemctl start systemd-nspawn@test
# systemctl status systemd-nspawn@test
● systemd-nspawn@test.service - Container test
   Loaded: loaded (/usr/lib/systemd/system/systemd-nspawn@.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2014-12-18 11:58:15 EST; 4s ago
     Docs: man:systemd-nspawn(1)
 Main PID: 9629 (systemd-nspawn)
   Status: "Container running."
   CGroup: /system.slice/system-systemd\x2dnspawn.slice/systemd-nspawn@test.service
           ├─9629 /usr/bin/systemd-nspawn --quiet --keep-unit --boot --link-journal=try-guest --directory=/var/lib/container/test
           ├─9630 /usr/lib/systemd/systemd
           └─system.slice
             ├─dbus.service
             │ └─9669 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
             ├─systemd-journald.service
             │ └─9645 /usr/lib/systemd/systemd-journald
             ├─systemd-logind.service
             │ └─9668 /usr/lib/systemd/systemd-logind
             └─console-getty.service
               └─9673 /sbin/agetty --noclear --keep-baud console 115200 38400 9600 vt102

Dec 18 11:58:16 arch systemd-nspawn[9629]: Starting Cleanup of Temporary Directories...
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Started Login Service.
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Started Permit User Sessions.
Dec 18 11:58:16 arch systemd-nspawn[9629]: Starting Console Getty...
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Started Console Getty.
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Reached target Login Prompts.
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Reached target Multi-User System.
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Reached target Graphical Interface.
Dec 18 11:58:16 arch systemd-nspawn[9629]: [  OK  ] Started Cleanup of Temporary

# machinectl reboot test
# systemctl status systemd-nspawn@test
● systemd-nspawn@test.service - Container test
   Loaded: loaded (/usr/lib/systemd/system/systemd-nspawn@.service; disabled; vendor preset: disabled)
   Active: inactive (dead)
     Docs: man:systemd-nspawn(1)

Dec 18 11:59:56 arch systemd-nspawn[9629]: [  OK  ] Stopped target Local File Systems (Pre).
Dec 18 11:59:56 arch systemd-nspawn[9629]: Stopping Remount Root and Kernel File Systems...
Dec 18 11:59:56 arch systemd-nspawn[9629]: [  OK  ] Stopped Remount Root and Kernel File Systems.
Dec 18 11:59:56 arch systemd-nspawn[9629]: [  OK  ] Started Generate shutdown-ramfs.
Dec 18 11:59:56 arch systemd-nspawn[9629]: [  OK  ] Reached target Shutdown.
Dec 18 11:59:56 arch systemd-nspawn[9629]: Sending SIGTERM to remaining processes...
Dec 18 11:59:56 arch systemd-nspawn[9629]: Sending SIGKILL to remaining processes...
Dec 18 11:59:56 arch systemd-nspawn[9629]: Rebooting.
Dec 18 11:59:56 arch systemd[1]: Stopping Container test...
Dec 18 11:59:56 arch systemd[1]: Stopped Container test.
Comment 1 Jonathan Liu 2014-12-18 02:13:22 UTC 
It seems to only fail if you let the container run for at least 40 seconds before rebooting it:
# systemctl restart systemd-nspawn@test; sleep 60; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
# systemctl restart systemd-nspawn@test; sleep 30; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: active (running) since Thu 2014-12-18 13:04:08 EST; 4s ago
# systemctl restart systemd-nspawn@test; sleep 45; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
# systemctl restart systemd-nspawn@test; sleep 37; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: active (running) since Thu 2014-12-18 13:06:27 EST; 4s ago
# systemctl restart systemd-nspawn@test; sleep 41; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
# systemctl restart systemd-nspawn@test; sleep 39; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: active (running) since Thu 2014-12-18 13:09:39 EST; 4s ago
# systemctl restart systemd-nspawn@test; sleep 40; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
# systemctl restart systemd-nspawn@test; sleep 40; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
# systemctl restart systemd-nspawn@test; sleep 40; machinectl reboot test; sleep 5; systemctl status systemd-nspawn@test | grep 'Active:'
   Active: inactive (dead)
Comment 2 Lennart Poettering 2015-02-04 16:23:20 UTC 
Hmm, this is weird. Any chance you can attach strace via "-p" to the running nspawn, then reproduce this, and then paste the last 20 log lines or so this generates here? There must be something wrong with how nspawn let's systemd know that it shall restart the daemon.

Also, any chance you can try to reproduce this on systemd git? We changed a lot in this area, and it might very likely already be fixed there.
Comment 3 Jonathan Liu 2015-02-10 00:42:59 UTC 
10 second sleep before reboot (reboot successful):
gettid()                = 14978
recvmsg(11, 0x7fff90b58060, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=11, events=POLLIN}], 1, {24, 999453000}, NULL, 8) = 1 ([{fd=11, revents=POLLIN}], left {24, 999376056})
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"OK 17a8c10a74d8494a8efb936654d93aec\r\nAGREE_UNIX_FD\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
sendmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
recvmsg(11, 0x7fff90b57ff0, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=11, events=POLLIN}], 1, {24, 999409000}, NULL, 8) = 1 ([{fd=11, revents=POLLIN}], left {24, 998332707})
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\f\0\0\0\1\0\0\0=\0\0\0\6\1s\0\7\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{":1.3035\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\7\0\0\0:1.3035\0", 68}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 68
sendmsg(11, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\4\0\0\0\2\0\0\0\237\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/machine1\0\0\0\0\0\0\0\3\1s\0\17\0\0\0GetMachineByPID\0\2\1s\0 \0\0\0org.freedesktop.machine1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0\10\1g\0\1u\0\0", 176}, {"\203:\0\0", 4}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 180
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\f\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0NameAcquired\0\0\0\0\6\1s\0\7\0\0\0:1.3035\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\7\0\0\0:1.3035\0", 148}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 148
recvmsg(11, 0x7fff90b58150, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=11, events=POLLIN}], 1, {24, 999765000}, NULL, 8) = 1 ([{fd=11, revents=POLLIN}], left {24, 999323324})
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1+\0\0\0\r\0\0\0000\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\7\0\0\0:1.3035\0\10\1g\0\1o\0\0\7\1s\0\7\0\0\0:1.3017\0&\0\0\0/org/freedesktop/machine1/machine/test\0", 83}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 83
sendmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\3\0\0\0\231\0\0\0\1\1o\0&\0\0\0/org/freedesktop/machine1/machine/test\0\0\3\1s\0\t\0\0\0Terminate\0\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.machine1.Machine\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0", 176}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 176
recvmsg(11, 0x7fff90b58160, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=11, events=POLLIN}], 1, {24, 999931000}, NULL, 8) = 1 ([{fd=11, revents=POLLIN}], left {24, 998788389})
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\20\0\0\0(\0\0\0\5\1u\0\3\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\7\0\0\0:1.3035\0\7\1s\0\7\0\0\0:1.3017\0", 32}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 32
close(11)               = 0
kill(14979, SIGKILL)    = 0
waitid(P_PID, 14979, {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=14979, si_uid=0, si_status=SIGHUP, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
close(6)                = 0
close(7)                = 0
close(8)                = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 6
sendmsg(6, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"STOPPING=1\nSTATUS=Terminating...", 32}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 32
close(6)                = 0
close(4)                = 0
close(5)                = 0
close(3)                = 0
exit_group(133)         = ?
+++ exited with 133 +++

60 second sleep before reboot (reboot unsuccessful):
gettid()                = 14393
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"OK 17a8c10a74d8494a8efb936654d93aec\r\nAGREE_UNIX_FD\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
sendmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\f\0\0\0\1\0\0\0=\0\0\0\6\1s\0\7\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{":1.2820\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\7\0\0\0:1.2820\0", 68}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 68
sendmsg(11, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\4\0\0\0\2\0\0\0\237\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/machine1\0\0\0\0\0\0\0\3\1s\0\17\0\0\0GetMachineByPID\0\2\1s\0 \0\0\0org.freedesktop.machine1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0\10\1g\0\1u\0\0", 176}, {":8\0\0", 4}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 180
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\f\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0NameAcquired\0\0\0\0\6\1s\0\7\0\0\0:1.2820\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\7\0\0\0:1.2820\0", 148}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 148
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1+\0\0\0\f\0\0\0000\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\7\0\0\0:1.2820\0\10\1g\0\1o\0\0\7\1s\0\7\0\0\0:1.2818\0&\0\0\0/org/freedesktop/machine1/machine/test\0", 83}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 83
sendmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\3\0\0\0\231\0\0\0\1\1o\0&\0\0\0/org/freedesktop/machine1/machine/test\0\0\3\1s\0\t\0\0\0Terminate\0\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.machine1.Machine\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0", 176}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 176
recvmsg(11, 0x7fff3a04c060, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=11, events=POLLIN}], 1, {24, 999399000}, NULL, 8) = 1 ([{fd=11, revents=POLLIN}], left {24, 998006212})
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\20\0\0\0(\0\0\0\5\1u\0\3\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(11, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\7\0\0\0:1.2820\0\7\1s\0\7\0\0\0:1.2818\0", 32}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 32
close(11)               = 0
kill(14394, SIGKILL)    = 0
waitid(P_PID, 14394, {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=14394, si_uid=0, si_status=SIGHUP, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
close(6)                = 0
close(7)                = 0
close(8)                = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 6
sendmsg(6, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"STOPPING=1\nSTATUS=Terminating...", 32}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 32
close(6)                = 0
close(4)                = 0
close(5)                = 0
close(3)                = 0
exit_group(133)         = ?
+++ exited with 133 +++

The SIGCONT in the reboot unsuccessful strace log looks peculiar.
Comment 4 Jonathan Liu 2015-02-10 01:24:21 UTC 
Tested again with systemd git 1c11181458990715e0ffd49e848baac5959e3c89 installed on both host and the container with sleep time of 60 seconds and 10 seconds. The container fails to reboot for both cases now.

60 second sleep before reboot (reboot unsuccessful):
gettid()                = 2523
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"OK 613e6eb1d637e4965336676c54d95ac3\r\nAGREE_UNIX_FD\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
sendmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{":1.844\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\0\0\0:1.844\0", 67}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 67
sendmsg(12, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\4\0\0\0\2\0\0\0\237\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/machine1\0\0\0\0\0\0\0\3\1s\0\17\0\0\0GetMachineByPID\0\2\1s\0 \0\0\0org.freedesktop.machine1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0\10\1g\0\1u\0\0", 176}, {"\334\t\0\0", 4}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 180
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\v\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0NameAcquired\0\0\0\0\6\1s\0\6\0\0\0:1.844\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\0\0\0:1.844\0", 147}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 147
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1+\0\0\0\36\0\0\0/\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\6\0\0\0:1.844\0\0\10\1g\0\1o\0\0\7\1s\0\6\0\0\0:1.680\0\0&\0\0\0/org/freedesktop/machine1/machine/test\0", 83}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 83
sendmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\3\0\0\0\231\0\0\0\1\1o\0&\0\0\0/org/freedesktop/machine1/machine/test\0\0\3\1s\0\t\0\0\0Terminate\0\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.machine1.Machine\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0", 176}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 176
recvmsg(12, 0x7fffe15c73e0, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=12, events=POLLIN}], 1, {24, 999700000}, NULL, 8) = 1 ([{fd=12, revents=POLLIN}], left {24, 999697784})
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\"\0\0\0'\0\0\0\5\1u\0\3\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\6\0\0\0:1.844\0\0\7\1s\0\6\0\0\0:1.680\0\0", 32}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 32
close(12)               = 0
kill(2524, SIGKILL)     = 0
waitid(P_PID, 2524, {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=2524, si_uid=0, si_status=SIGHUP, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
close(6)                = 0
close(7)                = 0
close(8)                = 0
close(10)               = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 6
sendmsg(6, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"STOPPING=1\nSTATUS=Terminating...", 32}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 32
close(6)                = 0
open("/run/systemd/nspawn/propagate/test", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC) = 6
fstatfs(6, {f_type=0x1021994, f_bsize=4096, f_blocks=506452, f_bfree=506100, f_bavail=506100, f_files=506452, f_ffree=505865, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
fstat(6, {st_dev=makedev(0, 15), st_ino=55456, st_mode=S_IFDIR|0600, st_nlink=2, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=40, st_atime=2015/02/10-12:20:42, st_mtime=2015/02/10-12:20:42, st_ctime=2015/02/10-12:20:42}) = 0
fcntl(6, F_GETFL)       = 0x78800 (flags O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_NOFOLLOW|O_NOATIME)
fcntl(6, F_SETFD, FD_CLOEXEC) = 0
getdents(6, {{d_ino=55456, d_off=1, d_reclen=24, d_name=".", d_type=DT_DIR} {d_ino=23207, d_off=2, d_reclen=24, d_name="..", d_type=DT_DIR}}, 32768) = 48
getdents(6, {}, 32768)  = 0
close(6)                = 0
rmdir("/run/systemd/nspawn/propagate/test") = 0
unlink("/var/lib/container/.#test.lck") = 0
close(3)                = 0
unlink("/run/systemd/nspawn/locks/inode-2067:6432234") = 0
close(4)                = 0
close(5)                = 0
exit_group(133)         = ?
+++ exited with 133 +++

10 second sleep before reboot (reboot unsuccessful):
gettid()                = 2331
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"OK 613e6eb1d637e4965336676c54d95ac3\r\nAGREE_UNIX_FD\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
sendmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{":1.699\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\0\0\0:1.699\0", 67}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 67
sendmsg(12, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\4\0\0\0\2\0\0\0\237\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/machine1\0\0\0\0\0\0\0\3\1s\0\17\0\0\0GetMachineByPID\0\2\1s\0 \0\0\0org.freedesktop.machine1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0\10\1g\0\1u\0\0", 176}, {"\34\t\0\0", 4}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 180
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\v\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0NameAcquired\0\0\0\0\6\1s\0\6\0\0\0:1.699\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\0\0\0:1.699\0", 147}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 147
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1+\0\0\0\20\0\0\0/\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\6\0\0\0:1.699\0\0\10\1g\0\1o\0\0\7\1s\0\6\0\0\0:1.680\0\0&\0\0\0/org/freedesktop/machine1/machine/test\0", 83}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 83
sendmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\3\0\0\0\231\0\0\0\1\1o\0&\0\0\0/org/freedesktop/machine1/machine/test\0\0\3\1s\0\t\0\0\0Terminate\0\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.machine1.Machine\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0", 176}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 176
recvmsg(12, 0x7fff06bb2860, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=12, events=POLLIN}], 1, {24, 999944000}, NULL, 8) = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
ppoll([{fd=12, events=POLLIN}], 1, {24, 998455394}, NULL, 8) = 1 ([{fd=12, revents=POLLIN}], left {24, 997227737})
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\24\0\0\0'\0\0\0\5\1u\0\3\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"\6\1s\0\6\0\0\0:1.699\0\0\7\1s\0\6\0\0\0:1.680\0\0", 32}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 32
close(12)               = 0
kill(2332, SIGKILL)     = 0
waitid(P_PID, 2332, {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=2332, si_uid=0, si_status=SIGHUP, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
close(6)                = 0
close(7)                = 0
close(8)                = 0
close(10)               = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 6
sendmsg(6, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"STOPPING=1\nSTATUS=Terminating...", 32}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 32
close(6)                = 0
open("/run/systemd/nspawn/propagate/test", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC) = 6
fstatfs(6, {f_type=0x1021994, f_bsize=4096, f_blocks=506452, f_bfree=506099, f_bavail=506099, f_files=506452, f_ffree=505864, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
fstat(6, {st_dev=makedev(0, 15), st_ino=50469, st_mode=S_IFDIR|0600, st_nlink=2, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=40, st_atime=2015/02/10-12:20:05, st_mtime=2015/02/10-12:20:05, st_ctime=2015/02/10-12:20:05}) = 0
fcntl(6, F_GETFL)       = 0x78800 (flags O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_NOFOLLOW|O_NOATIME)
fcntl(6, F_SETFD, FD_CLOEXEC) = 0
getdents(6, {{d_ino=50469, d_off=1, d_reclen=24, d_name=".", d_type=DT_DIR} {d_ino=23207, d_off=2, d_reclen=24, d_name="..", d_type=DT_DIR}}, 32768) = 48
getdents(6, {}, 32768)  = 0
close(6)                = 0
rmdir("/run/systemd/nspawn/propagate/test") = 0
unlink("/var/lib/container/.#test.lck") = 0
close(3)                = 0
unlink("/run/systemd/nspawn/locks/inode-2067:6432234") = 0
close(4)                = 0
close(5)                = 0
exit_group(133)         = ?
+++ exited with 133 +++
Comment 5 Lennart Poettering 2015-04-27 14:08:40 UTC 
Can you turn on debug logging in systemd and paste everything that systemd logs about the exiting nspawn service?

(turn on debug logging with systemd-analyze set-log-level debug)
Comment 6 Jonathan Liu 2015-04-28 09:07:02 UTC 
Created attachment 115394 [details]
systemd v219 debug log - start and reboot nspawn container

Log attached.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.