Hi Florian, "pelzflorian (Florian Pelz)" skribis: > 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): --8<---------------cut here---------------start------------->8--- 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. --8<---------------cut here---------------end--------------->8--- 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: --8<---------------cut here---------------start------------->8--- [ 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. --8<---------------cut here---------------end--------------->8--- 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 . It also reminds me of a discussion with Konrad about the best way to make this configurable. Ludo’.