Hi,
It seems to me that bug #624599 and #635777 are talking about the same
issue, thus this message goes to both.
To debug this problem, I’ve installed wheezy in a virtualbox VM and enabled the
serial port to go to /tmp/wheezy.pipe, then used mkfifo /tmp/wheezy.pipe and
ran the following script called follow.sh:
#!/bin/zsh
IFS=$'\n'
while :
do
read line
echo "$(date +'%X.%N') $line"
done
like this:
socat -d -d /tmp/wheezy.pipe - | ./follow.sh
I have then installed systemd 44-4, samba 2:3.6.6-3 and modified
/etc/default/grub to contain GRUB_CMDLINE_LINUX_DEFAULT="console=ttyS0
systemd.log_target=console systemd.log_level=debug init=/bin/systemd"
In the resulting logfiles with systemd 44-4, I interpret the reboot sequence
like this:
First, the reboot is scheduled and systemd adds a lot of jobs:
13:17:54.077835080 Trying to enqueue job reboot.target/start/replace
13:17:54.078445373 Installed new job reboot.target/start as 207
13:17:54.079062664 Installed new job reboot.service/start as 208
13:17:54.079694022 Installed new job shutdown.target/start as 209
13:17:54.080331569 Installed new job systemd-update-utmp-shutdown.service/start
as 210
--- systemd-44.orig/src/manager.c 2012-10-14 15:23:38.000000000 +0200
+++ systemd-44/src/manager.c 2012-10-14 16:23:57.869642186 +0200
@@ -1700,6 +1700,8 @@
int manager_add_job(Manager *m, JobType type, Unit *unit, JobMode mode, bool override, DBusError *e, Job **_ret) {
int r;
Job *ret;
+ Job *j;
+ Iterator i;
assert(m);
assert(type < _JOB_TYPE_MAX);
@@ -1711,6 +1713,30 @@
return -EINVAL;
}
+ if (type == JOB_RELOAD || type == JOB_RELOAD_OR_START || type == JOB_RESTART || type == JOB_TRY_RESTART) {
+ /* If final.target is queued (happens on poweroff, reboot and
+ * halt), we will not accept new reload jobs. They would not be
+ * executed ever anyways (since the shutdown comes first), but
+ * they block the shutdown process: when systemd tries to stop
+ * a unit such as [email protected], that unit might invoke a
+ * systemctl reload command, which blockingly waits (but only
+ * gets executed after all other queued units for the shutdown
+ * have been executed).
+ *
+ * See http://bugs.debian.org/624599 and
+ * http://bugs.debian.org/635777 */
+ HASHMAP_FOREACH(j, m->jobs, i) {
+ assert(j->installed);
+
+ if (strcmp(j->unit->id, "final.target") == 0) {
+ log_debug("final.target is queued, ignoring reload request");
+ dbus_set_error(e, BUS_ERROR_INVALID_JOB_MODE, "final.target is queued, ignoring reload request");
+ return -EINVAL;
+ }
+ }
+ }
+
+
if (mode == JOB_ISOLATE && !unit->allow_isolate) {
dbus_set_error(e, BUS_ERROR_NO_ISOLATION, "Operation refused, unit may not be isolated.");
return -EPERM;
…
13:17:54.241713303 Installed new job final.target/start as 281
13:17:54.242481254 Installed new job
console-kit-log-system-restart.service/start as 282
It then goes on the execute the jobs, and at some point in time gets a reload
request for samba:
13:17:54.834616091 Got D-Bus request:
org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
13:17:54.835327899 Trying to enqueue job samba.service/reload/replace
13:17:54.835985739 Installed new job samba.service/reload as 283
13:17:54.836630671 Enqueued job samba.service/reload as 283
This reload request blocks until it is executed, but systemd will only execute
it after finishing all other queued jobs, thus locking the situation
([email protected] cannot be stopped until the reload is completed, the reload
cannot complete until [email protected] is completed).
Ultimately, [email protected] times out and the sequence continues:
13:19:24.240183406 [email protected] stopping timed out. Terminating.
I have written a patch which works around this issue by denying reload and
restart requests when final.target is queued (it gets queued before
poweroff.service, reboot.service and halt.service), it is attached to this
message.
With the patch applied, the reboot sequence works smoothly, as you can observe
from the output:
15:28:54.924965520 Trying to enqueue job reboot.target/start/replace
15:28:54.925644182 Installed new job reboot.target/start as 204
15:28:54.928603812 Installed new job reboot.service/start as 205
…
15:29:00.075293851 Got D-Bus request:
org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
15:29:00.075934837 final.target is queued, ignoring reload request
15:29:00.076552572 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected()
on /org/freedesktop/DBus/Local
15:29:00.077173492 Received SIGCHLD from PID 747 (ifdown).
15:29:00.077774461 Got SIGCHLD for process 747 (ifdown)
15:29:00.078372169 Child 747 died (code=exited, status=0/SUCCESS)
15:29:01.755516484 [ 23.886593] Restarting system.
15:29:01.756118029 [ 23.886898] machine restart
Can you still reproduce the issue after re-building systemd with this
patch?
--
Best regards,
Michael
