bug#40572: installer networking: Connman detects no technologies on Acer Aspire

[Ludovic Courtès]

Hi Florian,

"pelzflorian (Florian Pelz)" <address@hidden> 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
<https://issues.guix.gnu.org/issue/35550>.  It also reminds me of a
discussion with Konrad about the best way to make this configurable.

Ludo’.

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)))))))