Hi Florian,
"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:
Toggle quote (11 lines)
> The installer crashed again after entering a newly invented hostname
> “a” (perhaps it was already in use from my previous attempt?). But
> later my normal hostname “florianmacbook” worked and network
> technologies failed. The hostname command displays “gnu” now.
>
> Here are the log files. From among the dbus trace files, only
> dbus.trace.301 is different after the installer crashed (see “diff
> logs/dbus.trace.301 logs/after-network-failed/dbus.trace.301”).
> Though you may be more interested in early trace logs/dbus.trace.228.
> But I’m going to sleep now. ;)
Uh, well deserved. :-)
The logs show very well what happened. From /var/log/messages
(stripped):
Toggle snippet (23 lines)
Apr 14 01:52:21 localhost vmunix: [ 12.733898] random: dbus-uuidgen: uninitialized urandom read (12 bytes read)
Apr 14 01:52:21 localhost vmunix: [ 27.690871] shepherd[1]: Service root has been started.
Apr 14 01:52:26 localhost shepherd[1]: Service dbus-system could not be started.
Apr 14 01:52:26 localhost shepherd[1]: Service networking depends on dbus-system.
Apr 14 01:52:26 localhost shepherd[1]: Service networking could not be started.
Apr 14 01:52:31 localhost shepherd[1]: Service dbus-system could not be started.
Apr 14 01:52:36 localhost shepherd[1]: Service dbus-system could not be started.
Apr 14 01:52:36 localhost shepherd[1]: Service wpa-supplicant depends on dbus-system.
Apr 14 01:52:36 localhost shepherd[1]: Service wpa-supplicant could not be started.
Apr 14 01:52:36 localhost shepherd[1]: Service loopback has been started.
Apr 14 01:52:41 localhost /gnu/store/bfvr3brh7f9dqh26jf49767ypbanqycm-gpm-1.20.7/sbin/gpm[258]: *** info [daemon/startup.c(136)]:
Apr 14 01:52:41 localhost /gnu/store/bfvr3brh7f9dqh26jf49767ypbanqycm-gpm-1.20.7/sbin/gpm[258]: Started gpm successfully. Entered daemon mode.
Apr 14 01:52:41 localhost shepherd[1]: Service gpm could not be started.
Apr 14 01:52:43 localhost dbus-daemon[244]: Failed to start message bus: Failed to bind socket "/var/run/dbus/system_bus_socket": Address already in use
Apr 14 01:52:45 localhost vmunix: [ 78.947812] mc: Linux media interface: v0.10
Apr 14 01:52:46 localhost shepherd[1]: Service dbus-system could not be started.
Apr 14 01:52:46 localhost shepherd[1]: Service term-tty1 depends on dbus-system.
Apr 14 01:52:46 localhost shepherd[1]: Service term-tty1 could not be started.
Apr 14 01:52:50 localhost dbus-daemon[262]: Failed to start message bus: Failed to open "/var/run/dbus/pid": File exists
Apr 14 01:53:14 localhost shepherd[1]: Service dbus-system has been started.
Apr 14 01:53:14 localhost shepherd[1]: Service term-tty1 has been started.
That alone shows the problem: dbus-system was initially wrongfully
considered as “not started”, thus subsequent attempts to start it result
in EADDRINUSE. This is confirmed by strace logs:
228 -> starts fine
openat(AT_FDCWD, "/var/run/dbus/pid", O_WRONLY|O_CREAT|O_EXCL, 0644) = 5
fcntl(5, F_GETFL) = 0x8001 (flags O_WRONLY|O_LARGEFILE)
fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(5, "228\n", 4) = 4
244 ->
sendto(3, "<28>Apr 14 01:52:43 dbus-daemon[244]: Failed to start message bus: Failed to bind socket \"/var/run/dbus/system_bus_socket\": Address already in use", 146, MSG_NOSIGNAL, NULL, 0) = 146
exit_group(1) = ?
262 ->
sendto(3, "<28>Apr 14 01:52:50 dbus-daemon[262]: Failed to start message bus: Failed to open \"/var/run/dbus/pid\": File exists", 114, MSG_NOSIGNAL, NULL, 0) = 114
exit_group(1) = ?
301 -> starts fine (did 228 die in the meantime? go figure)
openat(AT_FDCWD, "/var/run/dbus/pid", O_WRONLY|O_CREAT|O_EXCL, 0644) = 5
fcntl(5, F_GETFL) = 0x8001 (flags O_WRONLY|O_LARGEFILE)
fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(5, "301\n", 4) = 4
Everything seems to be extremely slow on this machine (booting from an
actual DVD, right?). For example:
Toggle snippet (9 lines)
[ 27.690871] shepherd[1]: Service root has been started.
[ 37.063759] shepherd[1]: starting services...
[...]
[ 39.969589] shepherd[1]: Service host-name has been started.
[ 41.959013] shepherd[1]: Service user-homes has been started.
That’s 27s before shepherd is started, and another 10s before “starting
services” (the only thing that happens in between in shepherd.conf is
loading .go files for the services.)
My guess is that cold-cache I/O is very slow. A plausible scenario is
that loading ‘dbus-daemon’ the first time takes several seconds;
dbus-daemon has enough time to fork, but it does not produce its PID
file until after the 5s ‘%pid-file-timeout’ has timeout has expired.
Thus, shepherd marks it as “failed to start” but it’s actually running.
To confirm this hypothesis, we need to run “strace -t”, see below (sorry
for not thinking about doing it!). If you can try again with the patch
below, that’s awesome. Then we’ll compare the timestamps in
/var/log/messages and those in the strace log.
If that’s confirmed, we can work around it locally by passing:
#:pid-file-timeout 15
to ‘make-forkexec-constructor’ for dbus-daemon or, alternately, setting
‘%pid-file-timeout’ globally from shepherd.conf.
You were right that it relates to
discussion with Konrad about the best way to make this configurable.
Ludo’.
Toggle diff (28 lines)
diff --git a/gnu/services/dbus.scm b/gnu/services/dbus.scm
index 7b3c8100e2..c6733ffce3 100644
--- a/gnu/services/dbus.scm
+++ b/gnu/services/dbus.scm
@@ -25,6 +25,7 @@
#:use-module ((gnu packages glib) #:select (dbus))
#:use-module (gnu packages polkit)
#:use-module (gnu packages admin)
+ #:use-module (gnu packages linux)
#:use-module (guix gexp)
#:use-module ((guix packages) #:select (package-name))
#:use-module (guix records)
@@ -186,9 +187,13 @@ includes the @code{etc/dbus-1/system.d} directories of each package listed in
(list (shepherd-service
(documentation "Run the D-Bus system daemon.")
(provision '(dbus-system))
- (requirement '(user-processes syslogd))
+ (requirement '(user-processes syslogd)) ;<- add 'host-name' and/or 'nscd'
(start #~(make-forkexec-constructor
- (list (string-append #$dbus "/bin/dbus-daemon")
+ (list #$(file-append strace "/bin/strace")
+ "-o" "/dbus.trace"
+ "-s" "500" "-ff"
+ "-t"
+ (string-append #$dbus "/bin/dbus-daemon")
"--nofork" "--system" "--syslog-only")
#:pid-file "/var/run/dbus/pid"))
(stop #~(make-kill-destructor)))))))
