GNU bug report logs - #34333
Docker daemon failing to start on boot

Previous Next

Package: guix;

Reported by: allan <at> adair.io

Date: Tue, 5 Feb 2019 16:01:01 UTC

Severity: normal

Done: Danny Milosavljevic <dannym <at> scratchpost.org>

Bug is archived. No further changes may be made.

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 34333 in the body.
You can then email your comments to 34333 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

View this report as an mbox folder, status mbox, maintainer mbox


Report forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Tue, 05 Feb 2019 16:01:01 GMT) Full text and rfc822 format available.

Acknowledgement sent to allan <at> adair.io:
New bug report received and forwarded. Copy sent to bug-guix <at> gnu.org. (Tue, 05 Feb 2019 16:01:02 GMT) Full text and rfc822 format available.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: allan <at> adair.io
To: bug-guix <at> gnu.org
Subject: Docker daemon failing to start on boot
Date: Tue, 05 Feb 2019 11:29:59 +0000
Hi, I am having an issue with the docker daemon as a service in guixsd. 
It seems that dockerd will not start on boot, but it will successfully 
start after running "guix system reconfigure".

Here is my config.scm:

(use-modules (gnu)
             (gnu system nss)
	     (gnu services)
	     (gnu services docker))
(use-service-modules desktop)
(use-package-modules certs gnome)

(operating-system
  (host-name "guixsd")
  (timezone "Europe/Oslo")
  (locale "en_US.utf8")

  (bootloader (bootloader-configuration
                (bootloader grub-bootloader)
                (target "/dev/sda")))

  (file-systems (cons (file-system
                        (device (file-system-label "my-root"))
                        (mount-point "/")
                        (type "ext4"))
                      %base-file-systems))

  (users (cons (user-account
                (name "allana")
                (group "users")
                (supplementary-groups '("wheel" "docker" "netdev"
                                        "audio" "video"))
                (home-directory "/home/allana"))
               %base-user-accounts))

  ;; This is where we specify system-wide packages.
  (packages (cons* nss-certs         ;for HTTPS access
                   gvfs              ;for user mounts
                   %base-packages))

  (services (cons* (console-keymap-service "no-latin1")
                   (gnome-desktop-service)
		   (service docker-service-type)
                   %desktop-services))

  ;; Allow resolution of '.local' host names with mDNS.
  (name-service-switch %mdns-host-lookup-nss))



After booting:



allana <at> guixsd ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is 
the docker daemon running?
allana <at> guixsd ~$ sudo herd status dockerd
Password:
Status of dockerd:
  It is stopped.
  It is enabled.
  Provides (dockerd).
  Requires (containerd file-system-/sys/fs/cgroup/blkio 
file-system-/sys/fs/cgroup/cpu file-system-/sys/fs/cgroup/cpuset 
file-system-/sys/fs/cgroup/devices file-system-/sys/fs/cgroup/memory).
  Conflicts with ().
  Will be respawned.
allana <at> guixsd ~$ sudo herd start dockerd
Service dockerd could not be started.
herd: failed to start service dockerd



But if I run:

allana <at> guixsd ~$ sudo guix reconfigure config.scm

...

allana <at> guixsd ~$ docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED      
       STATUS              PORTS               NAMES
allana <at> guixsd ~$ sudo herd status dockerd
Password:
Status of dockerd:
  It is started.
  Running value is 2123.
  It is enabled.
  Provides (dockerd).
  Requires (containerd file-system-/sys/fs/cgroup/blkio 
file-system-/sys/fs/cgroup/cpu file-system-/sys/fs/cgroup/cpuset 
file-system-/sys/fs/cgroup/devices file-system-/sys/fs/cgroup/memory).
  Conflicts with ().
  Will be respawned.


Dump from /var/log/messages:



Feb  5 10:06:37 localhost -- MARK --
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/hosts` was 
deleted, removing watch
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/hosts` was 
created, adding watch
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/hosts` was 
written to
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/services` was 
deleted, removing watch
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/services` was 
created, adding watch
Feb  5 10:15:47 localhost nscd: 319 monitored file `/etc/services` was 
written to
Feb  5 10:15:47 localhost NetworkManager[355]: <info>  [1549358147.5315] 
settings: hostname changed from (none) to "guixsd"
Feb  5 10:15:48 localhost shepherd[1]: Evaluating user expression (let* 
((services (map primitive-load (?))) # ?) ?).
Feb  5 10:15:48 localhost shepherd[1]: Service user-homes could not be 
started.
Feb  5 10:15:48 localhost shepherd[1]: Service term-auto could not be 
started.
Feb  5 10:15:49 localhost vmunix: [ 2965.192083] bridge: filtering via 
arp/ip/ip6tables is no longer available by default. Update your scripts 
to load br_netfilter if you need this.
Feb  5 10:15:49 localhost vmunix: [ 2965.194289] Bridge firewalling 
registered
Feb  5 10:15:49 localhost vmunix: [ 2965.405743] Initializing XFRM 
netlink socket
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.2361] 
manager: (docker0): new Bridge device 
(/org/freedesktop/NetworkManager/Devices/3)
Feb  5 10:15:49 localhost avahi-daemon[361]: Joining mDNS multicast 
group on interface docker0.IPv4 with address 172.17.0.1.
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3174] 
device (docker0): state change: unmanaged -> unavailable (reason 
'connection-assumed', internal state 'external')
Feb  5 10:15:49 localhost vmunix: [ 2965.500493] IPv6: 
ADDRCONF(NETDEV_UP): docker0: link is not ready
Feb  5 10:15:49 localhost avahi-daemon[361]: New relevant interface 
docker0.IPv4 for mDNS.
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3195] 
keyfile: add connection in-memory 
(33e2c9e2-62a1-4439-8fb5-be99034ffc7b,"docker0")
Feb  5 10:15:49 localhost avahi-daemon[361]: Registering new address 
record for 172.17.0.1 on docker0.IPv4.
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3203] 
device (docker0): state change: unavailable -> disconnected (reason 
'connection-assumed', internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3223] 
device (docker0): Activation: starting connection 'docker0' 
(33e2c9e2-62a1-4439-8fb5-be99034ffc7b)
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3236] 
device (docker0): state change: disconnected -> prepare (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3243] 
device (docker0): state change: prepare -> config (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3247] 
device (docker0): state change: config -> ip-config (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <warn>  [1549358149.3321] 
arping[0x82cc80,3]: arping could not be found; no ARPs will be sent
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3322] 
device (docker0): state change: ip-config -> ip-check (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3462] 
device (docker0): state change: ip-check -> secondaries (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3508] 
device (docker0): state change: secondaries -> activated (reason 'none', 
internal state 'external')
Feb  5 10:15:49 localhost NetworkManager[355]: <info>  [1549358149.3528] 
device (docker0): Activation: successful, device activated.
Feb  5 10:15:49 localhost shepherd[1]: Service dockerd has been started.
Feb  5 10:15:51 localhost NetworkManager[355]: <warn>  [1549358151.9250] 
arping[0x82cc80,3]: arping could not be found; no ARPs will be sent
Feb  5 10:16:10 localhost shepherd[1]: Exiting shepherd...
Feb  5 10:16:10 localhost ntpd[356]: ntpd exiting on signal 15 
(Terminated)
Feb  5 10:16:10 localhost ntpd[356]: 80.89.32.122 local addr 10.0.2.15 
-> <null>
Feb  5 10:16:10 localhost ntpd[356]: 31.185.27.200 local addr 10.0.2.15 
-> <null>
Feb  5 10:16:10 localhost ntpd[356]: 92.62.34.78 local addr 10.0.2.15 -> 
<null>
Feb  5 10:16:10 localhost syslogd: exiting on signal 15
Feb  5 10:16:49 localhost syslogd (GNU inetutils 1.9.4): restart
Feb  5 10:16:49 localhost vmunix: [    0.000000] Linux version 
4.20.6-gnu (nixbld@) (gcc version 7.4.0 (GCC)) #1 SMP 1
Feb  5 10:16:49 localhost vmunix: [    0.000000] Command line: 
BOOT_IMAGE=/gnu/store/fnpq4ndcjyai0rqlgj8x02qwlm88fc9d-linux-libre-4.20.6/bzImage 
--root=my-root 
--system=/gnu/store/b93pw0x9z120bilhiicics30f5y8fgj6-system 
--load=/gnu/store/b93pw0x9z120bilhiicics30f5y8fgj6-system/boot
Feb  5 10:16:49 localhost vmunix: [    0.000000] KERNEL supported cpus:
Feb  5 10:16:49 localhost vmunix: [    0.000000]   Intel GenuineIntel
Feb  5 10:16:49 localhost vmunix: [    0.000000]   AMD AuthenticAMD
Feb  5 10:16:49 localhost vmunix: [    0.000000]   Hygon HygonGenuine
Feb  5 10:16:49 localhost vmunix: [    0.000000]   Centaur CentaurHauls
Feb  5 10:16:49 localhost vmunix: [    0.000000] x86/fpu: Supporting 
XSAVE feature 0x001: 'x87 floating point registers'
Feb  5 10:16:49 localhost vmunix: [    0.000000] x86/fpu: Supporting 
XSAVE feature 0x002: 'SSE registers'
Feb  5 10:16:49 localhost vmunix: [    0.000000] x86/fpu: Supporting 
XSAVE feature 0x004: 'AVX registers'
Feb  5 10:16:49 localhost vmunix: [    0.000000] x86/fpu: 
xstate_offset[2]:  576, xstate_sizes[2]:  256
Feb  5 10:16:49 localhost vmunix: [    0.000000] x86/fpu: Enabled xstate 
features 0x7, context size is 832 bytes, using 'standard' format.
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-provided physical 
RAM map:
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x0000000000000000-0x000000000009fbff] usable
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x000000000009fc00-0x000000000009ffff] reserved
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x00000000000f0000-0x00000000000fffff] reserved
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x0000000000100000-0x00000000dffeffff] usable
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x00000000dfff0000-0x00000000dfffffff] ACPI data
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x00000000fec00000-0x00000000fec00fff] reserved
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x00000000fee00000-0x00000000fee00fff] reserved
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x00000000fffc0000-0x00000000ffffffff] reserved
Feb  5 10:16:49 localhost vmunix: [    0.000000] BIOS-e820: [mem 
0x0000000100000000-0x000000019fffffff] usable
Feb  5 10:16:49 localhost vmunix: [    0.000000] NX (Execute Disable) 
protection: active
Feb  5 10:16:49 localhost vmunix: [    0.000000] SMBIOS 2.5 present.
Feb  5 10:16:49 localhost vmunix: [    0.000000] DMI: innotek GmbH 
VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Feb  5 10:16:49 localhost vmunix: [    0.000000] Hypervisor detected: 
KVM
Feb  5 10:16:49 localhost vmunix: [    0.000000] kvm-clock: Using msrs 
4b564d01 and 4b564d00
Feb  5 10:16:49 localhost shepherd[1]: Service syslogd has been started.
Feb  5 10:16:49 localhost vmunix: [    0.000001] kvm-clock: cpu 0, msr 
13a574001, primary cpu clock
Feb  5 10:16:49 localhost vmunix: [    0.000001] kvm-clock: using sched 
offset of 5879650815 cycles
Feb  5 10:16:49 localhost vmunix: [    0.000006] clocksource: kvm-clock: 
mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 
881590591483 ns
Feb  5 10:16:49 localhost vmunix: [    0.000012] tsc: Detected 2904.004 
MHz processor
Feb  5 10:16:49 localhost vmunix: [    0.004133] last_pfn = 0x1a0000 
max_arch_pfn = 0x400000000
Feb  5 10:16:49 localhost vmunix: [    0.004164] Disabled
Feb  5 10:16:49 localhost vmunix: [    0.004167] x86/PAT: MTRRs 
disabled, skipping PAT initialization too.
Feb  5 10:16:49 localhost vmunix: [    0.004174] CPU MTRRs all blank - 
virtualized system.
Feb  5 10:16:49 localhost vmunix: [    0.004182] x86/PAT: Configuration 
[0-7]: WB  WT  UC- UC  WB  WT  UC- UC
Feb  5 10:16:49 localhost vmunix: [    0.004192] last_pfn = 0xdfff0 
max_arch_pfn = 0x400000000
Feb  5 10:16:49 localhost shepherd[1]: Service loopback has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.004273] found SMP MP-table at 
[mem 0x0009fff0-0x0009ffff] mapped at [(____ptrval____)]
Feb  5 10:16:49 localhost vmunix: [    0.140871] check: Scanning 1 areas 
for low memory corruption
Feb  5 10:16:49 localhost vmunix: [    0.141648] RAMDISK: [mem 
0x36a51000-0x3751ffff]
Feb  5 10:16:49 localhost vmunix: [    0.141660] ACPI: Early table 
checksum verification disabled
Feb  5 10:16:49 localhost vmunix: [    0.141686] ACPI: RSDP 
0x00000000000E0000 000024 (v02 VBOX  )
Feb  5 10:16:49 localhost shepherd[1]: Service virtual-terminal has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.141695] ACPI: XSDT 
0x00000000DFFF0030 00003C (v01 VBOX   VBOXXSDT 00000001 ASL  00000061)
Feb  5 10:16:49 localhost vmunix: [    0.141702] ACPI: FACP 
0x00000000DFFF00F0 0000F4 (v04 VBOX   VBOXFACP 00000001 ASL  00000061)
Feb  5 10:16:49 localhost vmunix: [    0.141708] ACPI: DSDT 
0x00000000DFFF0470 0021FF (v02 VBOX   VBOXBIOS 00000002 INTL 20100528)
Feb  5 10:16:49 localhost vmunix: [    0.141712] ACPI: FACS 
0x00000000DFFF0200 000040
Feb  5 10:16:49 localhost vmunix: [    0.141716] ACPI: FACS 
0x00000000DFFF0200 000040
Feb  5 10:16:49 localhost vmunix: [    0.141719] ACPI: APIC 
0x00000000DFFF0240 00005C (v02 VBOX   VBOXAPIC 00000001 ASL  00000061)
Feb  5 10:16:49 localhost vmunix: [    0.141723] ACPI: SSDT 
0x00000000DFFF02A0 0001CC (v01 VBOX   VBOXCPUT 00000002 INTL 20100528)
Feb  5 10:16:49 localhost vmunix: [    0.141963] No NUMA configuration 
found
Feb  5 10:16:49 localhost vmunix: [    0.141966] Faking a node at [mem 
0x0000000000000000-0x000000019fffffff]
Feb  5 10:16:49 localhost vmunix: [    0.141970] NODE_DATA(0) allocated 
[mem 0x19fffa000-0x19fffdfff]
Feb  5 10:16:49 localhost vmunix: [    0.142680] Zone ranges:
Feb  5 10:16:49 localhost vmunix: [    0.142684]   DMA32    [mem 
0x0000000000001000-0x00000000ffffffff]
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty6 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.142686]   Normal   [mem 
0x0000000100000000-0x000000019fffffff]
Feb  5 10:16:49 localhost vmunix: [    0.142688]   Device   empty
Feb  5 10:16:49 localhost vmunix: [    0.142690] Movable zone start for 
each node
Feb  5 10:16:49 localhost vmunix: [    0.142692] Early memory node 
ranges
Feb  5 10:16:49 localhost vmunix: [    0.142694]   node   0: [mem 
0x0000000000001000-0x000000000009efff]
Feb  5 10:16:49 localhost vmunix: [    0.142695]   node   0: [mem 
0x0000000000100000-0x00000000dffeffff]
Feb  5 10:16:49 localhost vmunix: [    0.142697]   node   0: [mem 
0x0000000100000000-0x000000019fffffff]
Feb  5 10:16:49 localhost vmunix: [    0.143870] Zeroed struct page in 
unavailable ranges: 114 pages
Feb  5 10:16:49 localhost vmunix: [    0.143873] Initmem setup node 0 
[mem 0x0000000000001000-0x000000019fffffff]
Feb  5 10:16:49 localhost vmunix: [    0.225477] ACPI: PM-Timer IO Port: 
0x4008
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty5 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.225571] IOAPIC[0]: apic_id 2, 
version 32, address 0xfec00000, GSI 0-23
Feb  5 10:16:49 localhost vmunix: [    0.225576] ACPI: INT_SRC_OVR (bus 
0 bus_irq 0 global_irq 2 dfl dfl)
Feb  5 10:16:49 localhost vmunix: [    0.225578] ACPI: INT_SRC_OVR (bus 
0 bus_irq 9 global_irq 9 low level)
Feb  5 10:16:49 localhost vmunix: [    0.225585] Using ACPI (MADT) for 
SMP configuration information
Feb  5 10:16:49 localhost vmunix: [    0.225593] smpboot: Allowing 2 
CPUs, 0 hotplug CPUs
Feb  5 10:16:49 localhost vmunix: [    0.225614] PM: Registered nosave 
memory: [mem 0x00000000-0x00000fff]
Feb  5 10:16:49 localhost vmunix: [    0.225617] PM: Registered nosave 
memory: [mem 0x0009f000-0x0009ffff]
Feb  5 10:16:49 localhost vmunix: [    0.225619] PM: Registered nosave 
memory: [mem 0x000a0000-0x000effff]
Feb  5 10:16:49 localhost vmunix: [    0.225621] PM: Registered nosave 
memory: [mem 0x000f0000-0x000fffff]
Feb  5 10:16:49 localhost vmunix: [    0.225623] PM: Registered nosave 
memory: [mem 0xdfff0000-0xdfffffff]
Feb  5 10:16:49 localhost vmunix: [    0.225625] PM: Registered nosave 
memory: [mem 0xe0000000-0xfebfffff]
Feb  5 10:16:49 localhost vmunix: [    0.225627] PM: Registered nosave 
memory: [mem 0xfec00000-0xfec00fff]
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty4 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.225629] PM: Registered nosave 
memory: [mem 0xfec01000-0xfedfffff]
Feb  5 10:16:49 localhost vmunix: [    0.225631] PM: Registered nosave 
memory: [mem 0xfee00000-0xfee00fff]
Feb  5 10:16:49 localhost vmunix: [    0.225633] PM: Registered nosave 
memory: [mem 0xfee01000-0xfffbffff]
Feb  5 10:16:49 localhost vmunix: [    0.225635] PM: Registered nosave 
memory: [mem 0xfffc0000-0xffffffff]
Feb  5 10:16:49 localhost vmunix: [    0.225638] [mem 
0xe0000000-0xfebfffff] available for PCI devices
Feb  5 10:16:49 localhost vmunix: [    0.225640] Booting paravirtualized 
kernel on KVM
Feb  5 10:16:49 localhost vmunix: [    0.225645] clocksource: 
refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 
7645519600211568 ns
Feb  5 10:16:49 localhost vmunix: [    0.225656] random: 
get_random_bytes called from start_kernel+0x99/0x51c with crng_init=0
Feb  5 10:16:49 localhost vmunix: [    0.225662] setup_percpu: 
NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:2 nr_node_ids:1
Feb  5 10:16:49 localhost vmunix: [    0.226183] percpu: Embedded 45 
pages/cpu @(____ptrval____) s146840 r8192 d29288 u1048576
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty3 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.226218] PV qspinlock hash table 
entries: 256 (order: 0, 4096 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.226224] Built 1 zonelists, 
mobility grouping on.  Total pages: 1548154
Feb  5 10:16:49 localhost vmunix: [    0.226226] Policy zone: Normal
Feb  5 10:16:49 localhost vmunix: [    0.226229] Kernel command line: 
BOOT_IMAGE=/gnu/store/fnpq4ndcjyai0rqlgj8x02qwlm88fc9d-linux-libre-4.20.6/bzImage 
--root=my-root 
--system=/gnu/store/b93pw0x9z120bilhiicics30f5y8fgj6-system 
--load=/gnu/store/b93pw0x9z120bilhiicics30f5y8fgj6-system/boot
Feb  5 10:16:49 localhost vmunix: [    0.252611] Memory: 
6090508K/6291000K available (12293K kernel code, 1470K rwdata, 3984K 
rodata, 1836K init, 2724K bss, 200492K reserved, 0K cma-reserved)
Feb  5 10:16:49 localhost vmunix: [    0.253199] SLUB: HWalign=64, 
Order=0-3, MinObjects=0, CPUs=2, Nodes=1
Feb  5 10:16:49 localhost vmunix: [    0.253218] Kernel/User page tables 
isolation: enabled
Feb  5 10:16:49 localhost vmunix: [    0.253238] ftrace: allocating 
39556 entries in 155 pages
Feb  5 10:16:49 localhost vmunix: [    0.286687] rcu: Hierarchical RCU 
implementation.
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty2 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.286691] rcu: 	RCU restricting 
CPUs from NR_CPUS=256 to nr_cpu_ids=2.
Feb  5 10:16:49 localhost vmunix: [    0.286694] rcu: RCU calculated 
value of scheduler-enlistment delay is 25 jiffies.
Feb  5 10:16:49 localhost vmunix: [    0.286695] rcu: Adjusting geometry 
for rcu_fanout_leaf=16, nr_cpu_ids=2
Feb  5 10:16:49 localhost vmunix: [    0.291153] NR_IRQS: 16640, 
nr_irqs: 440, preallocated irqs: 16
Feb  5 10:16:49 localhost vmunix: [    0.306506] Console: colour VGA+ 
80x25
Feb  5 10:16:49 localhost vmunix: [    0.351776] printk: console [tty0] 
enabled
Feb  5 10:16:49 localhost vmunix: [    0.352163] ACPI: Core revision 
20181003
Feb  5 10:16:49 localhost vmunix: [    0.352640] APIC: Switch to 
symmetric I/O mode setup
Feb  5 10:16:49 localhost vmunix: [    0.353395] x2apic enabled
Feb  5 10:16:49 localhost vmunix: [    0.354008] Switched APIC routing 
to physical x2apic.
Feb  5 10:16:49 localhost vmunix: [    0.355939] ..TIMER: vector=0x30 
apic1=0 pin1=2 apic2=-1 pin2=-1
Feb  5 10:16:49 localhost vmunix: [    0.356365] clocksource: tsc-early: 
mask: 0xffffffffffffffff max_cycles: 0x29dc09beef1, max_idle_ns: 
440795310252 ns
Feb  5 10:16:49 localhost vmunix: [    0.357056] Calibrating delay loop 
(skipped) preset value.. 5808.00 BogoMIPS (lpj=11616016)
Feb  5 10:16:49 localhost vmunix: [    0.357657] pid_max: default: 32768 
minimum: 301
Feb  5 10:16:49 localhost vmunix: [    0.357979] LSM: Security Framework 
initializing
Feb  5 10:16:49 localhost shepherd[1]: Service term-tty1 has been 
started.
Feb  5 10:16:49 localhost vmunix: [    0.358275] Yama: becoming mindful.
Feb  5 10:16:49 localhost vmunix: [    0.358571] AppArmor: AppArmor 
initialized
Feb  5 10:16:49 localhost vmunix: [    0.365111] Dentry cache hash table 
entries: 1048576 (order: 11, 8388608 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.367155] Inode-cache hash table 
entries: 524288 (order: 10, 4194304 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.367706] Mount-cache hash table 
entries: 16384 (order: 5, 131072 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.368222] Mountpoint-cache hash 
table entries: 16384 (order: 5, 131072 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.369143] mce: CPU supports 0 MCE 
banks
Feb  5 10:16:49 localhost vmunix: [    0.369521] Last level iTLB 
entries: 4KB 64, 2MB 8, 4MB 8
Feb  5 10:16:49 localhost vmunix: [    0.369949] Last level dTLB 
entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
Feb  5 10:16:49 localhost vmunix: [    0.370431] Spectre V2 : 
Mitigation: Full generic retpoline
Feb  5 10:16:49 localhost vmunix: [    0.370872] Spectre V2 : Spectre v2 
/ SpectreRSB mitigation: Filling RSB on context switch
Feb  5 10:16:49 localhost vmunix: [    0.371589] Speculative Store 
Bypass: Vulnerable
Feb  5 10:16:49 localhost vmunix: [    0.372180] Freeing SMP 
alternatives memory: 28K
Feb  5 10:16:49 localhost vmunix: [    0.377043] smpboot: CPU0: Intel(R) 
Core(TM) i7-7500U CPU @ 2.70GHz (family: 0x6, model: 0x8e, stepping: 
0x9)
Feb  5 10:16:49 localhost shepherd[1]: Service term-auto could not be 
started.
Feb  5 10:16:49 localhost vmunix: [    0.377043] Performance Events: 
unsupported p6 CPU model 142 no PMU driver, software events only.
Feb  5 10:16:49 localhost vmunix: [    0.377043] rcu: Hierarchical SRCU 
implementation.
Feb  5 10:16:49 localhost vmunix: [    0.377043] NMI watchdog: Perf NMI 
watchdog permanently disabled
Feb  5 10:16:49 localhost vmunix: [    0.377043] smp: Bringing up 
secondary CPUs ...
Feb  5 10:16:49 localhost vmunix: [    0.377141] x86: Booting SMP 
configuration:
Feb  5 10:16:49 localhost vmunix: [    0.377549] .... node  #0, CPUs:    
  #1
Feb  5 10:16:49 localhost vmunix: [    0.069599] kvm-clock: cpu 1, msr 
13a574041, secondary cpu clock
Feb  5 10:16:49 localhost vmunix: [    0.069599] mce: CPU supports 0 MCE 
banks
Feb  5 10:16:49 localhost vmunix: [    0.379916] smp: Brought up 1 node, 
2 CPUs
Feb  5 10:16:49 localhost vmunix: [    0.381049] smpboot: Max logical 
packages: 1
Feb  5 10:16:49 localhost vmunix: [    0.381467] smpboot: Total of 2 
processors activated (11616.01 BogoMIPS)
Feb  5 10:16:49 localhost vmunix: [    0.382274] devtmpfs: initialized
Feb  5 10:16:49 localhost vmunix: [    0.382274] x86/mm: Memory block 
size: 128MB
Feb  5 10:16:49 localhost vmunix: [    0.385115] clocksource: jiffies: 
mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 
ns
Feb  5 10:16:49 localhost vmunix: [    0.385820] futex hash table 
entries: 512 (order: 3, 32768 bytes)
Feb  5 10:16:49 localhost vmunix: [    0.386292] pinctrl core: 
initialized pinctrl subsystem
Feb  5 10:16:49 localhost shepherd[1]: Service console-font-tty1 has 
been started.
Feb  5 10:16:49 localhost vmunix: [    0.386775] RTC time:  9:16:41, 
date: 02/05/19
Feb  5 10:16:49 localhost vmunix: [    0.387249] NET: Registered 
protocol family 16
Feb  5 10:16:49 localhost vmunix: [    0.387715] audit: initializing 
netlink subsys (disabled)
Feb  5 10:16:49 localhost vmunix: [    0.388115] audit: type=2000 
audit(1549358208.770:1): state=initialized audit_enabled=0 res=1
Feb  5 10:16:49 localhost vmunix: [    0.389051] cpuidle: using governor 
ladder
Feb  5 10:16:49 localhost vmunix: [    0.389415] cpuidle: using governor 
menu
Feb  5 10:16:50 localhost vmunix: [    0.389781] ACPI: bus type PCI 
registered
Feb  5 10:16:50 localhost vmunix: [    0.390114] acpiphp: ACPI Hot Plug 
PCI Controller Driver version: 0.5
Feb  5 10:16:50 localhost vmunix: [    0.390665] PCI: Using 
configuration type 1 for base access
Feb  5 10:16:50 localhost vmunix: [    0.393093] HugeTLB registered 2.00 
MiB page size, pre-allocated 0 pages
Feb  5 10:16:50 localhost vmunix: [    0.393603] ACPI: Added _OSI(Module 
Device)
Feb  5 10:16:50 localhost vmunix: [    0.393603] ACPI: Added 
_OSI(Processor Device)
Feb  5 10:16:50 localhost vmunix: [    0.394103] ACPI: Added _OSI(3.0 
_SCP Extensions)
Feb  5 10:16:50 localhost vmunix: [    0.394500] ACPI: Added 
_OSI(Processor Aggregator Device)
Feb  5 10:16:50 localhost vmunix: [    0.394936] ACPI: Added 
_OSI(Linux-Dell-Video)
Feb  5 10:16:50 localhost vmunix: [    0.395317] ACPI: Added 
_OSI(Linux-Lenovo-NV-HDMI-Audio)
Feb  5 10:16:50 localhost shepherd[1]: Service console-font-tty2 has 
been started.
Feb  5 10:16:50 localhost vmunix: [    0.398388] ACPI: 2 ACPI AML tables 
successfully acquired and loaded
Feb  5 10:16:50 localhost vmunix: [    0.401220] ACPI: Interpreter 
enabled
Feb  5 10:16:50 localhost vmunix: [    0.401530] ACPI: (supports S0 S5)
Feb  5 10:16:50 localhost vmunix: [    0.401834] ACPI: Using IOAPIC for 
interrupt routing
Feb  5 10:16:50 localhost vmunix: [    0.402377] PCI: Using host bridge 
windows from ACPI; if necessary, use "pci=nocrs" and report a bug
Feb  5 10:16:50 localhost vmunix: [    0.403123] ACPI: Enabled 2 GPEs in 
block 00 to 07
Feb  5 10:16:50 localhost vmunix: [    0.409628] ACPI: PCI Root Bridge 
[PCI0] (domain 0000 [bus 00-ff])
Feb  5 10:16:50 localhost vmunix: [    0.410161] acpi PNP0A03:00: _OSC: 
OS supports [ASPM ClockPM Segments MSI]
Feb  5 10:16:50 localhost vmunix: [    0.410635] acpi PNP0A03:00: _OSC: 
not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI]
Feb  5 10:16:50 localhost vmunix: [    0.411299] acpi PNP0A03:00: fail 
to add MMCONFIG information, can't access extended PCI configuration 
space under this bridge.
Feb  5 10:16:50 localhost vmunix: [    0.412482] PCI host bridge to bus 
0000:00
Feb  5 10:16:50 localhost vmunix: [    0.412836] pci_bus 0000:00: root 
bus resource [io  0x0000-0x0cf7 window]
Feb  5 10:16:50 localhost vmunix: [    0.413043] pci_bus 0000:00: root 
bus resource [io  0x0d00-0xffff window]
Feb  5 10:16:50 localhost shepherd[1]: Service console-font-tty3 has 
been started.
Feb  5 10:16:50 localhost vmunix: [    0.413049] pci_bus 0000:00: root 
bus resource [mem 0x000a0000-0x000bffff window]
Feb  5 10:16:50 localhost vmunix: [    0.413711] pci_bus 0000:00: root 
bus resource [mem 0xe0000000-0xfdffffff window]
Feb  5 10:16:50 localhost vmunix: [    0.414343] pci_bus 0000:00: root 
bus resource [bus 00-ff]
Feb  5 10:16:50 localhost vmunix: [    0.419482] pci 0000:00:01.1: 
legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
Feb  5 10:16:50 localhost vmunix: [    0.420020] pci 0000:00:01.1: 
legacy IDE quirk: reg 0x14: [io  0x03f6]
Feb  5 10:16:50 localhost vmunix: [    0.420503] pci 0000:00:01.1: 
legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
Feb  5 10:16:50 localhost vmunix: [    0.421065] pci 0000:00:01.1: 
legacy IDE quirk: reg 0x1c: [io  0x0376]
Feb  5 10:16:50 localhost shepherd[1]: Service console-font-tty4 has 
been started.
Feb  5 10:16:50 localhost vmunix: [    0.499981] pci 0000:00:07.0: 
quirk: [io  0x4000-0x403f] claimed by PIIX4 ACPI
Feb  5 10:16:50 localhost vmunix: [    0.500561] pci 0000:00:07.0: 
quirk: [io  0x4100-0x410f] claimed by PIIX4 SMB
Feb  5 10:16:50 localhost shepherd[1]: Service console-font-tty5 has 
been started.
Feb  5 10:16:50 localhost vmunix: [    0.530275] ACPI: PCI Interrupt 
Link [LNKA] (IRQs 5 9 10 *11)
Feb  5 10:16:50 localhost vmunix: [    0.530994] ACPI: PCI Interrupt 
Link [LNKB] (IRQs 5 9 *10 11)
Feb  5 10:16:50 localhost vmunix: [    0.531493] ACPI: PCI Interrupt 
Link [LNKC] (IRQs 5 *9 10 11)
Feb  5 10:16:50 localhost vmunix: [    0.531983] ACPI: PCI Interrupt 
Link [LNKD] (IRQs 5 9 10 *11)
Feb  5 10:16:50 localhost vmunix: [    0.533199] pci 0000:00:02.0: 
vgaarb: setting as boot VGA device
Feb  5 10:16:50 localhost vmunix: [    0.533453] pci 0000:00:02.0: 
vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
Feb  5 10:16:50 localhost vmunix: [    0.534028] pci 0000:00:02.0: 
vgaarb: bridge control possible
Feb  5 10:16:50 localhost vmunix: [    0.534402] vgaarb: loaded
Feb  5 10:16:50 localhost vmunix: [    0.534809] SCSI subsystem 
initialized
Feb  5 10:16:50 localhost vmunix: [    0.535115] ACPI: bus type USB 
registered
Feb  5 10:16:50 localhost vmunix: [    0.535115] usbcore: registered new 
interface driver usbfs
Feb  5 10:16:50 localhost vmunix: [    0.535115] usbcore: registered new 
interface driver hub
Feb  5 10:16:50 localhost vmunix: [    0.535115] usbcore: registered new 
device driver usb
Feb  5 10:16:50 localhost vmunix: [    0.535115] EDAC MC: Ver: 3.0.0
Feb  5 10:16:50 localhost shepherd[1]: Service console-font-tty6 has 
been started.
Feb  5 10:16:50 localhost vmunix: [    0.537261] PCI: Using ACPI for IRQ 
routing
Feb  5 10:16:50 localhost vmunix: [    0.537893] NetLabel: Initializing
Feb  5 10:16:50 localhost vmunix: [    0.538243] NetLabel:  domain hash 
size = 128
Feb  5 10:16:50 localhost vmunix: [    0.538600] NetLabel:  protocols = 
UNLABELED CIPSOv4 CALIPSO
Feb  5 10:16:50 localhost vmunix: [    0.539052] NetLabel:  unlabeled 
traffic allowed by default
Feb  5 10:16:50 localhost vmunix: [    0.539494] clocksource: Switched 
to clocksource kvm-clock
Feb  5 10:16:50 localhost vmunix: [    0.552438] VFS: Disk quotas 
dquot_6.6.0
Feb  5 10:16:50 localhost vmunix: [    0.553250] VFS: Dquot-cache hash 
table entries: 512 (order 0, 4096 bytes)
Feb  5 10:16:50 localhost vmunix: [    0.554025] AppArmor: AppArmor 
Filesystem Enabled
Feb  5 10:16:50 localhost vmunix: [    0.554564] pnp: PnP ACPI init
Feb  5 10:16:50 localhost vmunix: [    0.556077] pnp: PnP ACPI: found 2 
devices
Feb  5 10:16:50 localhost vmunix: [    0.567704] clocksource: acpi_pm: 
mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
Feb  5 10:16:50 localhost vmunix: [    0.568592] NET: Registered 
protocol family 2
Feb  5 10:16:50 localhost vmunix: [    0.569232] 
tcp_listen_portaddr_hash hash table entries: 4096 (order: 4, 65536 
bytes)
Feb  5 10:16:50 localhost vmunix: [    0.569931] TCP established hash 
table entries: 65536 (order: 7, 524288 bytes)
Feb  5 10:16:50 localhost vmunix: [    0.570685] TCP bind hash table 
entries: 65536 (order: 8, 1048576 bytes)
Feb  5 10:16:50 localhost vmunix: [    0.571780] TCP: Hash tables 
configured (established 65536 bind 65536)
Feb  5 10:16:50 localhost vmunix: [    0.572322] UDP hash table entries: 
4096 (order: 5, 131072 bytes)
Feb  5 10:16:50 localhost vmunix: [    0.573193] UDP-Lite hash table 
entries: 4096 (order: 5, 131072 bytes)
Feb  5 10:16:50 localhost vmunix: [    0.574090] NET: Registered 
protocol family 1
Feb  5 10:16:50 localhost vmunix: [    0.574647] pci 0000:00:00.0: 
Limiting direct PCI/PCI transfers
Feb  5 10:16:50 localhost vmunix: [    0.575307] pci 0000:00:01.0: 
Activating ISA DMA hang workarounds
Feb  5 10:16:50 localhost vmunix: [    0.576041] pci 0000:00:02.0: Video 
device with shadowed ROM at [mem 0x000c0000-0x000dffff]
Feb  5 10:16:50 localhost vmunix: [    0.578641] Trying to unpack rootfs 
image as initramfs...
Feb  5 10:16:50 localhost vmunix: [    0.847453] Freeing initrd memory: 
11068K
Feb  5 10:16:50 localhost vmunix: [    0.847852] PCI-DMA: Using software 
bounce buffering for IO (SWIOTLB)
Feb  5 10:16:50 localhost vmunix: [    0.848343] software IO TLB: mapped 
[mem 0xdbff0000-0xdfff0000] (64MB)
Feb  5 10:16:50 localhost vmunix: [    0.849014] RAPL PMU: API unit is 
2^-32 Joules, 5 fixed counters, 10737418240 ms ovfl timer
Feb  5 10:16:50 localhost vmunix: [    0.849771] RAPL PMU: hw unit of 
domain pp0-core 2^-0 Joules
Feb  5 10:16:50 localhost vmunix: [    0.850223] RAPL PMU: hw unit of 
domain package 2^-0 Joules
Feb  5 10:16:50 localhost vmunix: [    0.850671] RAPL PMU: hw unit of 
domain dram 2^-0 Joules
Feb  5 10:16:50 localhost vmunix: [    0.851183] RAPL PMU: hw unit of 
domain pp1-gpu 2^-0 Joules
Feb  5 10:16:50 localhost vmunix: [    0.851891] RAPL PMU: hw unit of 
domain psys 2^-0 Joules
Feb  5 10:16:50 localhost vmunix: [    0.852582] clocksource: tsc: mask: 
0xffffffffffffffff max_cycles: 0x29dc09beef1, max_idle_ns: 440795310252 
ns
Feb  5 10:16:50 localhost vmunix: [    0.854294] platform rtc_cmos: 
registered platform RTC device (no PNP device found)
Feb  5 10:16:50 localhost vmunix: [    0.855341] check: Scanning for low 
memory corruption every 60 seconds
Feb  5 10:16:50 localhost vmunix: [    0.857333] Initialise system 
trusted keyrings
Feb  5 10:16:50 localhost vmunix: [    0.858137] workingset: 
timestamp_bits=40 max_order=21 bucket_order=0
Feb  5 10:16:50 localhost vmunix: [    0.861513] zbud: loaded
Feb  5 10:16:50 localhost vmunix: [    0.863142] Allocating IMA 
blacklist keyring.
Feb  5 10:16:50 localhost vmunix: [    0.874094] Key type asymmetric 
registered
Feb  5 10:16:50 localhost vmunix: [    0.874687] Asymmetric key parser 
'x509' registered
Feb  5 10:16:50 localhost vmunix: [    0.875318] Block layer SCSI 
generic (bsg) driver version 0.4 loaded (major 247)
Feb  5 10:16:50 localhost vmunix: [    0.876302] io scheduler noop 
registered
Feb  5 10:16:50 localhost vmunix: [    0.876689] io scheduler deadline 
registered (default)
Feb  5 10:16:50 localhost vmunix: [    0.877228] io scheduler cfq 
registered
Feb  5 10:16:50 localhost vmunix: [    0.877952] shpchp: Standard Hot 
Plug PCI Controller Driver version: 0.4
Feb  5 10:16:50 localhost vmunix: [    0.878929] ACPI: AC Adapter [AC] 
(on-line)
Feb  5 10:16:50 localhost vmunix: [    0.879528] input: Power Button as 
/devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
Feb  5 10:16:50 localhost vmunix: [    0.880267] ACPI: Power Button 
[PWRF]
Feb  5 10:16:50 localhost vmunix: [    0.880745] input: Sleep Button as 
/devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
Feb  5 10:16:50 localhost vmunix: [    0.881488] ACPI: Sleep Button 
[SLPF]
Feb  5 10:16:50 localhost vmunix: [    0.883491] battery: ACPI: Battery 
Slot [BAT0] (battery present)
Feb  5 10:16:50 localhost vmunix: [    0.884195] Serial: 8250/16550 
driver, 32 ports, IRQ sharing enabled
Feb  5 10:16:50 localhost vmunix: [    0.889728] Linux agpgart interface 
v0.103
Feb  5 10:16:50 localhost vmunix: [    0.896488] brd: module loaded
Feb  5 10:16:50 localhost vmunix: [    0.898376] loop: module loaded
Feb  5 10:16:50 localhost vmunix: [    0.899528] scsi host0: ata_piix
Feb  5 10:16:50 localhost vmunix: [    0.899962] scsi host1: ata_piix
Feb  5 10:16:50 localhost vmunix: [    0.900270] ata1: PATA max UDMA/33 
cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
Feb  5 10:16:50 localhost vmunix: [    0.900711] ata2: PATA max UDMA/33 
cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
Feb  5 10:16:50 localhost vmunix: [    0.901310] libphy: Fixed MDIO Bus: 
probed
Feb  5 10:16:50 localhost vmunix: [    0.901660] tun: Universal TUN/TAP 
device driver, 1.6
Feb  5 10:16:50 localhost vmunix: [    0.902349] PPP generic driver 
version 2.4.2
Feb  5 10:16:50 localhost vmunix: [    0.902820] ehci_hcd: USB 2.0 
'Enhanced' Host Controller (EHCI) Driver
Feb  5 10:16:50 localhost vmunix: [    0.903352] ehci-pci: EHCI PCI 
platform driver
Feb  5 10:16:50 localhost vmunix: [    0.903776] ehci-platform: EHCI 
generic platform driver
Feb  5 10:16:50 localhost vmunix: [    0.904235] ohci_hcd: USB 1.1 
'Open' Host Controller (OHCI) Driver
Feb  5 10:16:50 localhost vmunix: [    0.904755] ohci-pci: OHCI PCI 
platform driver
Feb  5 10:16:50 localhost vmunix: [    0.905173] ohci-platform: OHCI 
generic platform driver
Feb  5 10:16:50 localhost vmunix: [    0.905651] uhci_hcd: USB Universal 
Host Controller Interface driver
Feb  5 10:16:50 localhost vmunix: [    0.906899] xhci_hcd 0000:00:0c.0: 
xHCI Host Controller
Feb  5 10:16:50 localhost vmunix: [    0.907321] xhci_hcd 0000:00:0c.0: 
new USB bus registered, assigned bus number 1
Feb  5 10:16:50 localhost vmunix: [    0.910017] xhci_hcd 0000:00:0c.0: 
hcc params 0x04000000 hci version 0x100 quirks 0x000000000000b930
Feb  5 10:16:50 localhost vmunix: [    0.911469] usb usb1: New USB 
device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.20
Feb  5 10:16:50 localhost vmunix: [    0.912472] usb usb1: New USB 
device strings: Mfr=3, Product=2, SerialNumber=1
Feb  5 10:16:50 localhost vmunix: [    0.913928] usb usb1: Product: xHCI 
Host Controller
Feb  5 10:16:50 localhost vmunix: [    0.914497] usb usb1: Manufacturer: 
Linux 4.20.6-gnu xhci-hcd
Feb  5 10:16:50 localhost vmunix: [    0.915120] usb usb1: SerialNumber: 
0000:00:0c.0
Feb  5 10:16:50 localhost vmunix: [    0.916083] hub 1-0:1.0: USB hub 
found
Feb  5 10:16:50 localhost vmunix: [    0.916694] hub 1-0:1.0: 8 ports 
detected
Feb  5 10:16:50 localhost vmunix: [    0.917871] xhci_hcd 0000:00:0c.0: 
xHCI Host Controller
Feb  5 10:16:50 localhost vmunix: [    0.918541] xhci_hcd 0000:00:0c.0: 
new USB bus registered, assigned bus number 2
Feb  5 10:16:50 localhost vmunix: [    0.919467] xhci_hcd 0000:00:0c.0: 
Host supports USB 3.0  SuperSpeed
Feb  5 10:16:50 localhost vmunix: [    0.920491] usb usb2: New USB 
device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.20
Feb  5 10:16:50 localhost vmunix: [    0.921264] usb usb2: New USB 
device strings: Mfr=3, Product=2, SerialNumber=1
Feb  5 10:16:50 localhost vmunix: [    0.922201] usb usb2: Product: xHCI 
Host Controller
Feb  5 10:16:50 localhost vmunix: [    0.922676] usb usb2: Manufacturer: 
Linux 4.20.6-gnu xhci-hcd
Feb  5 10:16:50 localhost vmunix: [    0.923221] usb usb2: SerialNumber: 
0000:00:0c.0
Feb  5 10:16:50 localhost vmunix: [    0.923891] hub 2-0:1.0: USB hub 
found
Feb  5 10:16:50 localhost vmunix: [    0.924384] hub 2-0:1.0: 6 ports 
detected
Feb  5 10:16:50 localhost vmunix: [    0.925270] i8042: PNP: PS/2 
Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
Feb  5 10:16:50 localhost vmunix: [    0.926755] serio: i8042 KBD port 
at 0x60,0x64 irq 1
Feb  5 10:16:50 localhost vmunix: [    0.927148] serio: i8042 AUX port 
at 0x60,0x64 irq 12
Feb  5 10:16:50 localhost vmunix: [    0.927694] mousedev: PS/2 mouse 
device common for all mice
Feb  5 10:16:50 localhost vmunix: [    0.928456] input: AT Translated 
Set 2 keyboard as /devices/platform/i8042/serio0/input/input2
Feb  5 10:16:50 localhost vmunix: [    0.929615] rtc_cmos rtc_cmos: 
registered as rtc0
Feb  5 10:16:50 localhost vmunix: [    0.930001] rtc_cmos rtc_cmos: 
alarms up to one day, 114 bytes nvram
Feb  5 10:16:50 localhost vmunix: [    0.930429] i2c /dev entries driver
Feb  5 10:16:50 localhost vmunix: [    0.930773] device-mapper: uevent: 
version 1.0.3
Feb  5 10:16:50 localhost vmunix: [    0.931232] device-mapper: ioctl: 
4.39.0-ioctl (2018-04-03) initialised: dm-devel <at> redhat.com
Feb  5 10:16:50 localhost vmunix: [    0.931882] ledtrig-cpu: registered 
to indicate activity on CPUs
Feb  5 10:16:50 localhost vmunix: [    0.932486] NET: Registered 
protocol family 10
Feb  5 10:16:50 localhost vmunix: [    0.933083] Segment Routing with 
IPv6
Feb  5 10:16:50 localhost vmunix: [    0.933386] NET: Registered 
protocol family 17
Feb  5 10:16:50 localhost vmunix: [    0.934017] Key type dns_resolver 
registered
Feb  5 10:16:50 localhost vmunix: [    0.934640] sched_clock: Marking 
stable (868984986, 65599564)->(1043027987, -108443437)
Feb  5 10:16:50 localhost vmunix: [    0.936118] registered taskstats 
version 1
Feb  5 10:16:50 localhost vmunix: [    0.936585] Loading compiled-in 
X.509 certificates
Feb  5 10:16:50 localhost vmunix: [    0.937112] zswap: loaded using 
pool lzo/zbud
Feb  5 10:16:50 localhost vmunix: [    0.939407] Key type big_key 
registered
Feb  5 10:16:50 localhost vmunix: [    0.940375] Key type trusted 
registered
Feb  5 10:16:50 localhost vmunix: [    0.941493] Key type encrypted 
registered
Feb  5 10:16:50 localhost vmunix: [    0.941961] AppArmor: AppArmor sha1 
policy hashing enabled
Feb  5 10:16:50 localhost vmunix: [    0.942404] ima: No TPM chip found, 
activating TPM-bypass!
Feb  5 10:16:50 localhost vmunix: [    0.942836] ima: Allocated hash 
algorithm: sha1
Feb  5 10:16:50 localhost vmunix: [    0.943235] evm: Initialising EVM 
extended attributes:
Feb  5 10:16:50 localhost vmunix: [    0.943631] evm: security.selinux
Feb  5 10:16:50 localhost vmunix: [    0.943940] evm: security.SMACK64
Feb  5 10:16:50 localhost vmunix: [    0.944247] evm: 
security.SMACK64EXEC
Feb  5 10:16:50 localhost vmunix: [    0.944573] evm: 
security.SMACK64TRANSMUTE
Feb  5 10:16:50 localhost vmunix: [    0.944896] evm: 
security.SMACK64MMAP
Feb  5 10:16:50 localhost vmunix: [    0.945198] evm: security.apparmor
Feb  5 10:16:50 localhost vmunix: [    0.945517] evm: security.ima
Feb  5 10:16:50 localhost vmunix: [    0.945791] evm: 
security.capability
Feb  5 10:16:50 localhost vmunix: [    0.946113] evm: HMAC attrs: 0x1
Feb  5 10:16:50 localhost vmunix: [    0.946622]   Magic number: 
7:23:272
Feb  5 10:16:50 localhost vmunix: [    0.947003] rtc_cmos rtc_cmos: 
setting system clock to 2019-02-05 09:16:41 UTC (1549358201)
Feb  5 10:16:50 localhost vmunix: [    1.061992] ata1.00: ATA-6: VBOX 
HARDDISK, 1.0, max UDMA/133
Feb  5 10:16:50 localhost vmunix: [    1.062963] ata1.00: 209715200 
sectors, multi 128: LBA
Feb  5 10:16:50 localhost vmunix: [    1.064886] scsi 0:0:0:0: 
Direct-Access     ATA      VBOX HARDDISK    1.0  PQ: 0 ANSI: 5
Feb  5 10:16:50 localhost vmunix: [    1.070972] sd 0:0:0:0: [sda] 
209715200 512-byte logical blocks: (107 GB/100 GiB)
Feb  5 10:16:50 localhost vmunix: [    1.072394] sd 0:0:0:0: Attached 
scsi generic sg0 type 0
Feb  5 10:16:50 localhost vmunix: [    1.073474] sd 0:0:0:0: [sda] Write 
Protect is off
Feb  5 10:16:50 localhost vmunix: [    1.074379] sd 0:0:0:0: [sda] Write 
cache: enabled, read cache: enabled, doesn't support DPO or FUA
Feb  5 10:16:50 localhost vmunix: [    1.077753]  sda: sda1
Feb  5 10:16:50 localhost vmunix: [    1.079051] sd 0:0:0:0: [sda] 
Attached SCSI disk
Feb  5 10:16:50 localhost vmunix: [    1.083128] Freeing unused kernel 
image memory: 1836K
Feb  5 10:16:50 localhost vmunix: [    1.111282] Write protecting the 
kernel read-only data: 18432k
Feb  5 10:16:50 localhost vmunix: [    1.112585] Freeing unused kernel 
image memory: 2032K
Feb  5 10:16:50 localhost vmunix: [    1.113227] Freeing unused kernel 
image memory: 112K
Feb  5 10:16:50 localhost vmunix: [    1.113734] Run /init as init 
process
Feb  5 10:16:50 localhost vmunix: [    1.225875] usbcore: registered new 
interface driver usb-storage
Feb  5 10:16:50 localhost vmunix: [    1.229518] usbcore: registered new 
interface driver uas
Feb  5 10:16:50 localhost vmunix: [    1.231779] hidraw: raw HID events 
driver (C) Jiri Kosina
Feb  5 10:16:50 localhost vmunix: [    1.232798] usbcore: registered new 
interface driver usbhid
Feb  5 10:16:50 localhost vmunix: [    1.233195] usbhid: USB HID core 
driver
Feb  5 10:16:50 localhost vmunix: [    1.254221] isci: Intel(R) C600 SAS 
Controller Driver - version 1.2.0
Feb  5 10:16:50 localhost vmunix: [    1.257325] usb 1-1: new full-speed 
USB device number 2 using xhci_hcd
Feb  5 10:16:50 localhost vmunix: [    1.290864] EXT4-fs (sda1): mounted 
filesystem with ordered data mode. Opts: (null)
Feb  5 10:16:50 localhost vmunix: [    1.516923] random: fast init done
Feb  5 10:16:50 localhost vmunix: [    1.517375] usb 1-1: New USB device 
found, idVendor=80ee, idProduct=0021, bcdDevice= 1.00
Feb  5 10:16:50 localhost vmunix: [    1.518137] usb 1-1: New USB device 
strings: Mfr=1, Product=3, SerialNumber=0
Feb  5 10:16:50 localhost vmunix: [    1.518702] usb 1-1: Product: USB 
Tablet
Feb  5 10:16:50 localhost vmunix: [    1.519119] usb 1-1: Manufacturer: 
VirtualBox
Feb  5 10:16:50 localhost vmunix: [    1.520842] input: VirtualBox USB 
Tablet as 
/devices/pci0000:00/0000:00:0c.0/usb1/1-1/1-1:1.0/0003:80EE:0021.0001/input/input4
Feb  5 10:16:50 localhost vmunix: [    1.522214] hid-generic 
0003:80EE:0021.0001: input,hidraw0: USB HID v1.10 Mouse [VirtualBox USB 
Tablet] on usb-0000:00:0c.0-1/input0
Feb  5 10:16:50 localhost vmunix: [    1.573552] usb 2-1: new SuperSpeed 
Gen 1 USB device number 2 using xhci_hcd
Feb  5 10:16:50 localhost vmunix: [    1.596234] usb 2-1: New USB device 
found, idVendor=0bc2, idProduct=ab2d, bcdDevice= 1.00
Feb  5 10:16:50 localhost vmunix: [    1.597055] usb 2-1: New USB device 
strings: Mfr=2, Product=3, SerialNumber=1
Feb  5 10:16:50 localhost vmunix: [    1.598054] usb 2-1: Product: Ultra 
Slim MT
Feb  5 10:16:50 localhost vmunix: [    1.598518] usb 2-1: Manufacturer: 
Seagate
Feb  5 10:16:50 localhost vmunix: [    1.598950] usb 2-1: SerialNumber: 
NA95GN93
Feb  5 10:16:50 localhost vmunix: [    1.615725] usb 2-1: USB controller 
0000:00:0c.0 does not support streams, which are required by the UAS 
driver.
Feb  5 10:16:50 localhost vmunix: [    1.616432] usb 2-1: Please try an 
other USB controller if you wish to use UAS.
Feb  5 10:16:50 localhost vmunix: [    1.616972] usb-storage 2-1:1.0: 
USB Mass Storage device detected
Feb  5 10:16:50 localhost vmunix: [    1.617945] scsi host2: usb-storage 
2-1:1.0
Feb  5 10:16:50 localhost vmunix: [    1.915360] random: shepherd: 
uninitialized urandom read (4096 bytes read)
Feb  5 10:16:50 localhost vmunix: [    2.112226] shepherd[1]: Service 
root has been started.
Feb  5 10:16:50 localhost vmunix: [    2.574825] shepherd[1]: starting 
services...
Feb  5 10:16:50 localhost vmunix: [    2.577239] shepherd[1]: Service 
root-file-system has been started.
Feb  5 10:16:50 localhost vmunix: [    2.579486] shepherd[1]: Service 
user-file-systems has been started.
Feb  5 10:16:50 localhost vmunix: [    2.597269] shepherd[1]: waiting 
for udevd...
Feb  5 10:16:50 localhost vmunix: [    2.626323] scsi 2:0:0:0: 
Direct-Access     Seagate  Ultra Slim MT    0304 PQ: 0 ANSI: 6
Feb  5 10:16:50 localhost vmunix: [    2.627181] sd 2:0:0:0: Attached 
scsi generic sg1 type 0
Feb  5 10:16:50 localhost vmunix: [    2.628647] sd 2:0:0:0: [sdb] 
3907029167 512-byte logical blocks: (2.00 TB/1.82 TiB)
Feb  5 10:16:50 localhost vmunix: [    2.630651] sd 2:0:0:0: [sdb] Write 
Protect is off
Feb  5 10:16:50 localhost vmunix: [    2.632262] sd 2:0:0:0: [sdb] Write 
cache: enabled, read cache: enabled, doesn't support DPO or FUA
Feb  5 10:16:50 localhost vmunix: [    2.644218] udevd[226]: starting 
version 3.2.5
Feb  5 10:16:50 localhost vmunix: [    2.651929] random: udevd: 
uninitialized urandom read (16 bytes read)
Feb  5 10:16:50 localhost vmunix: [    2.652967] random: udevd: 
uninitialized urandom read (16 bytes read)
Feb  5 10:16:50 localhost vmunix: [    2.658355]  sdb: sdb1
Feb  5 10:16:50 localhost vmunix: [    2.662893] sd 2:0:0:0: [sdb] 
Attached SCSI disk
Feb  5 10:16:50 localhost vmunix: [    2.711145] udevd[226]: starting 
eudev-3.2.5
Feb  5 10:16:50 localhost vmunix: [    3.100347] urandom_read: 3 
callbacks suppressed
Feb  5 10:16:50 localhost vmunix: [    3.100348] random: udevd: 
uninitialized urandom read (16 bytes read)
Feb  5 10:16:50 localhost vmunix: [    3.101328] random: udevd: 
uninitialized urandom read (16 bytes read)
Feb  5 10:16:50 localhost vmunix: [    3.101954] random: udevd: 
uninitialized urandom read (16 bytes read)
Feb  5 10:16:50 localhost vmunix: [    3.115850] udevd[226]: no sender 
credentials received, message ignored
Feb  5 10:16:50 localhost vmunix: [    3.223838] ACPI: Video Device 
[GFX0] (multi-head: yes  rom: no  post: no)
Feb  5 10:16:50 localhost vmunix: [    3.225554] piix4_smbus 
0000:00:07.0: SMBus Host Controller at 0x4100, revision 0
Feb  5 10:16:50 localhost vmunix: [    3.226881] input: Video Bus as 
/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/LNXVIDEO:00/input/input5
Feb  5 10:16:50 localhost vmunix: [    3.231807] e1000: Intel(R) 
PRO/1000 Network Driver - version 7.3.21-k8-NAPI
Feb  5 10:16:50 localhost vmunix: [    3.232591] e1000: Copyright (c) 
1999-2006 Intel Corporation.
Feb  5 10:16:50 localhost vmunix: [    3.236849] vboxguest: 
host-version: 5.2.22r126460 0x1
Feb  5 10:16:50 localhost vmunix: [    3.257490] vbg_heartbeat_init: 
Setting up heartbeat to trigger every 2000 milliseconds
Feb  5 10:16:50 localhost vmunix: [    3.261704] input: VirtualBox mouse 
integration as /devices/pci0000:00/0000:00:04.0/input/input6
Feb  5 10:16:50 localhost vmunix: [    3.269374] vboxguest: misc device 
minor 55, IRQ 20, I/O port d020, MMIO at 0x00000000f0400000 (size 
0x0000000000400000)
Feb  5 10:16:50 localhost vmunix: [    3.331752] input: PC Speaker as 
/devices/platform/pcspkr/input/input8
Feb  5 10:16:50 localhost vmunix: [    3.360607] Error: Driver 'pcspkr' 
is already registered, aborting...
Feb  5 10:16:50 localhost vmunix: [    3.381988] vboxvideo: module is 
from the staging directory, the quality is unknown, you have been 
warned.
Feb  5 10:16:50 localhost vmunix: [    3.396850] [drm] VRAM 08000000
Feb  5 10:16:50 localhost vmunix: [    3.405888] [TTM] Zone  kernel: 
Available graphics memory: 3052792 kiB
Feb  5 10:16:50 localhost vmunix: [    3.406651] [TTM] Zone   dma32: 
Available graphics memory: 2097152 kiB
Feb  5 10:16:50 localhost vmunix: [    3.407376] [TTM] Initializing pool 
allocator
Feb  5 10:16:50 localhost vmunix: [    3.407955] [TTM] Initializing DMA 
pool allocator
Feb  5 10:16:50 localhost vmunix: [    3.413515] fbcon: vboxdrmfb (fb0) 
is primary device
Feb  5 10:16:50 localhost vmunix: [    3.435817] Console: switching to 
colour frame buffer device 100x37
Feb  5 10:16:50 localhost vmunix: [    3.441896] cryptd: max_cpu_qlen 
set to 1000
Feb  5 10:16:50 localhost vmunix: [    3.444636] vboxvideo 0000:00:02.0: 
fb0: vboxdrmfb frame buffer device
Feb  5 10:16:50 localhost vmunix: [    3.473380] [drm] Initialized 
vboxvideo 1.0.0 20130823 for 0000:00:02.0 on minor 0
Feb  5 10:16:50 localhost vmunix: [    3.547752] input: ImExPS/2 Generic 
Explorer Mouse as /devices/platform/i8042/serio1/input/input7
Feb  5 10:16:50 localhost vmunix: [    3.603503] random: crng init done
Feb  5 10:16:50 localhost vmunix: [    3.603534] random: 1 urandom 
warning(s) missed due to ratelimiting
Feb  5 10:16:50 localhost vmunix: [    3.621045] AVX2 version of 
gcm_enc/dec engaged.
Feb  5 10:16:50 localhost vmunix: [    3.621068] AES CTR mode by8 
optimization enabled
Feb  5 10:16:50 localhost vmunix: [    3.698176] Error: Driver 'pcspkr' 
is already registered, aborting...
Feb  5 10:16:50 localhost vmunix: [    5.234134] e1000 0000:00:03.0 
eth0: (PCI:33MHz:32-bit) 08:00:27:05:e5:16
Feb  5 10:16:50 localhost vmunix: [    5.234186] e1000 0000:00:03.0 
eth0: Intel(R) PRO/1000 Network Connection
Feb  5 10:16:50 localhost vmunix: [    6.359585] e1000 0000:00:03.0 
enp0s3: renamed from eth0
Feb  5 10:16:50 localhost vmunix: [    6.717424] snd_intel8x0 
0000:00:05.0: intel8x0_measure_ac97_clock: measured 289540 usecs (32768 
samples)
Feb  5 10:16:50 localhost vmunix: [    6.718057] snd_intel8x0 
0000:00:05.0: measured clock 113172 rejected
Feb  5 10:16:50 localhost vmunix: [    7.111538] snd_intel8x0 
0000:00:05.0: intel8x0_measure_ac97_clock: measured 62702 usecs (52800 
samples)
Feb  5 10:16:50 localhost vmunix: [    7.112731] snd_intel8x0 
0000:00:05.0: measured clock 842078 rejected
Feb  5 10:16:50 localhost vmunix: [    7.554863] snd_intel8x0 
0000:00:05.0: intel8x0_measure_ac97_clock: measured 63241 usecs (52800 
samples)
Feb  5 10:16:50 localhost vmunix: [    7.555534] snd_intel8x0 
0000:00:05.0: measured clock 834901 rejected
Feb  5 10:16:50 localhost vmunix: [    7.555923] snd_intel8x0 
0000:00:05.0: clocking to 48000
Feb  5 10:16:50 localhost vmunix: [    7.614123] shepherd[1]: Service 
udev has been started.
Feb  5 10:16:50 localhost vmunix: [    7.620079] shepherd[1]: Service 
file-system-/dev/pts has been started.
Feb  5 10:16:50 localhost vmunix: [    7.624460] shepherd[1]: Service 
file-system-/dev/shm has been started.
Feb  5 10:16:50 localhost vmunix: [    7.627768] shepherd[1]: Service 
file-system-/gnu/store has been started.
Feb  5 10:16:50 localhost vmunix: [    7.632415] shepherd[1]: Service 
file-system-/run/systemd has been started.
Feb  5 10:16:50 localhost vmunix: [    7.637661] shepherd[1]: Service 
file-system-/run/user has been started.
Feb  5 10:16:50 localhost vmunix: [    7.642228] shepherd[1]: Service 
file-system-/sys/fs/cgroup has been started.
Feb  5 10:16:50 localhost vmunix: [    7.645880] shepherd[1]: Service 
file-system-/sys/fs/cgroup/elogind has been started.
Feb  5 10:16:50 localhost vmunix: [    7.650668] shepherd[1]: Service 
file-system-/sys/fs/cgroup/cpuset has been started.
Feb  5 10:16:50 localhost vmunix: [    7.656170] shepherd[1]: Service 
file-system-/sys/fs/cgroup/cpu has been started.
Feb  5 10:16:50 localhost vmunix: [    7.660985] shepherd[1]: Service 
file-system-/sys/fs/cgroup/cpuacct has been started.
Feb  5 10:16:50 localhost vmunix: [    7.668727] shepherd[1]: Service 
file-system-/sys/fs/cgroup/memory has been started.
Feb  5 10:16:50 localhost vmunix: [    7.672988] shepherd[1]: Service 
file-system-/sys/fs/cgroup/devices has been started.
Feb  5 10:16:50 localhost vmunix: [    7.677617] shepherd[1]: Service 
file-system-/sys/fs/cgroup/freezer has been started.
Feb  5 10:16:50 localhost vmunix: [    7.683015] shepherd[1]: Service 
file-system-/sys/fs/cgroup/blkio has been started.
Feb  5 10:16:50 localhost vmunix: [    7.686707] shepherd[1]: Service 
file-system-/sys/fs/cgroup/perf_event has been started.
Feb  5 10:16:50 localhost vmunix: [    7.689707] shepherd[1]: Service 
file-systems has been started.
Feb  5 10:16:50 localhost vmunix: [    7.705657] shepherd[1]: Service 
urandom-seed has been started.
Feb  5 10:16:50 localhost vmunix: [    7.708740] shepherd[1]: Service 
user-processes has been started.
Feb  5 10:16:50 localhost vmunix: [    7.712567] shepherd[1]: Service 
host-name has been started.
Feb  5 10:16:50 localhost vmunix: [    7.722636] shepherd[1]: Service 
user-homes could not be started.
Feb  5 10:16:50 localhost vmunix: [    8.888557] shepherd[1]: Service 
nscd has been started.
Feb  5 10:16:50 localhost vmunix: [    8.895107] shepherd[1]: Service 
guix-daemon has been started.
Feb  5 10:16:50 localhost shepherd[1]: Service dbus-system has been 
started.
Feb  5 10:16:50 localhost shepherd[1]: Service wpa-supplicant has been 
started.
Feb  5 10:16:50 localhost shepherd[1]: Service networking has been 
started.
Feb  5 10:16:50 localhost shepherd[1]: Service ntpd has been started.
Feb  5 10:16:50 localhost shepherd[1]: Service elogind has been started.
Feb  5 10:16:50 localhost shepherd[1]: Service upower-daemon has been 
started.
Feb  5 10:16:51 localhost avahi-daemon[359]: Found user 'avahi' (UID 
994) and group 'avahi' (GID 979).
Feb  5 10:16:51 localhost avahi-daemon[359]: Successfully dropped root 
privileges.
Feb  5 10:16:51 localhost avahi-daemon[359]: avahi-daemon 0.7 starting 
up.
Feb  5 10:16:51 localhost avahi-daemon[359]: WARNING: No NSS support for 
mDNS detected, consider installing nss-mdns!
Feb  5 10:16:51 localhost avahi-daemon[359]: Successfully called 
chroot().
Feb  5 10:16:51 localhost avahi-daemon[359]: Successfully dropped 
remaining capabilities.
Feb  5 10:16:51 localhost avahi-daemon[359]: Loading service file 
/services/sftp-ssh.service.
Feb  5 10:16:51 localhost avahi-daemon[359]: Loading service file 
/services/ssh.service.
Feb  5 10:16:51 localhost avahi-daemon[359]: Network interface 
enumeration completed.
Feb  5 10:16:51 localhost avahi-daemon[359]: Server startup complete. 
Host name is guixsd.local. Local service cookie is 1225535440.
Feb  5 10:16:51 localhost avahi-daemon[359]: Service "guixsd" 
(/services/ssh.service) successfully established.
Feb  5 10:16:51 localhost avahi-daemon[359]: Service "guixsd" 
(/services/sftp-ssh.service) successfully established.
Feb  5 10:16:51 localhost shepherd[1]: Service avahi-daemon has been 
started.
Feb  5 10:16:51 localhost shepherd[1]: Service xorg-server has been 
started.
Feb  5 10:16:51 localhost ntpd[354]: ntpd 4.2.8p12 <at> 1.3728-o Mon Dec  3 
15:10:30 UTC 2018 (1): Starting
Feb  5 10:16:51 localhost ntpd[354]: Command line: 
/gnu/store/wcsjiw5nfv861ysnv00m2hj9fil3h51k-ntp-4.2.8p12/bin/ntpd -n -c 
/gnu/store/1l1yf5dss8r9pqxklaax32s6bkah09c6-ntpd.conf -u ntpd
Feb  5 10:16:51 localhost shepherd[1]: Service containerd has been 
started.
Feb  5 10:16:51 localhost ntpd[354]: proto: precision = 0.155 usec (-23)
Feb  5 10:16:51 localhost ntpd[354]: restrict default: KOD does nothing 
without LIMITED.
Feb  5 10:16:51 localhost ntpd[354]: restrict ::: KOD does nothing 
without LIMITED.
Feb  5 10:16:51 localhost ntpd[354]: Listen and drop on 0 v6wildcard 
[::]:123
Feb  5 10:16:51 localhost ntpd[354]: Listen and drop on 1 v4wildcard 
0.0.0.0:123
Feb  5 10:16:51 localhost ntpd[354]: Listen normally on 2 lo 
127.0.0.1:123
Feb  5 10:16:51 localhost ntpd[354]: Listen normally on 3 lo [::1]:123
Feb  5 10:16:51 localhost ntpd[354]: Listening on routing socket on fd 
#20 for interface updates
Feb  5 10:16:51 localhost ntpd[354]: kernel reports TIME_ERROR: 0x41: 
Clock Unsynchronized
Feb  5 10:16:51 localhost ntpd[354]: kernel reports TIME_ERROR: 0x41: 
Clock Unsynchronized
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3005] 
NetworkManager (version 1.8.4) is starting... (for the first time)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3006] 
Read config: 
/gnu/store/3cp48fvxfivj2255bbxj7363qj33ajs9-NetworkManager.conf
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3243] 
manager[0x121d0c0]: monitoring kernel firmware directory 
'/lib/firmware'.
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3291] 
policy: hostname management mode: default
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3309] 
dns-mgr[0x1229160]: init: dns=default, rc-manager=symlink
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3329] 
manager[0x121d0c0]: rfkill: WiFi hardware radio set enabled
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.3331] 
manager[0x121d0c0]: rfkill: WWAN hardware radio set enabled
Feb  5 10:16:51 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.nm_dispatcher' requested by ':1.4' (uid=0 pid=353 
comm="/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-networ") (using 
servicehelper)
Feb  5 10:16:51 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.nm_dispatcher'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4106] 
settings: loaded plugin keyfile: (c) 2007 - 2016 Red Hat, Inc.  To 
report bugs please use the NetworkManager mailing list.
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4427] 
keyfile: new connection 
/etc/NetworkManager/system-connections/Tenda_2F20A0 
(dafd4a72-d2d2-48e4-a2f0-36b6d632a0c5,"Tenda_2F20A0")
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4500] 
settings: hostname: couldn't get property from hostnamed
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4634] 
dhcp-init: Using DHCP client 'dhclient'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4636] 
manager: rfkill: WiFi enabled by radio killswitch; enabled by state file
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4636] 
manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4651] 
manager: Networking is enabled by state file
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4673] 
Loaded device plugin: NMBondDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4675] 
Loaded device plugin: NMBridgeDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4676] 
Loaded device plugin: NMDummyDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4695] 
Loaded device plugin: NMEthernetDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4696] 
Loaded device plugin: NMInfinibandDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4699] 
Loaded device plugin: NMIPTunnelDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4705] 
Loaded device plugin: NMMacsecDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4706] 
Loaded device plugin: NMMacvlanDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4713] 
Loaded device plugin: NMTunDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4714] 
Loaded device plugin: NMVethDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4715] 
Loaded device plugin: NMVlanDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4716] 
Loaded device plugin: NMVxlanDeviceFactory (internal)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4763] 
Loaded device plugin: NMAtmManager 
(/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-network-manager-1.8.4/lib/NetworkManager/libnm-device-plugin-adsl.so)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.4840] 
Loaded device plugin: NMWifiFactory 
(/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-network-manager-1.8.4/lib/NetworkManager/libnm-device-plugin-wifi.so)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5339] 
Loaded device plugin: NMBluezManager 
(/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-network-manager-1.8.4/lib/NetworkManager/libnm-device-plugin-bluetooth.so)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5402] 
Loaded device plugin: NMWwanFactory 
(/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-network-manager-1.8.4/lib/NetworkManager/libnm-device-plugin-wwan.so)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5440] 
device (lo): link connected
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5458] 
manager: (lo): new Generic device 
(/org/freedesktop/NetworkManager/Devices/1)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5480] 
manager: (enp0s3): new Ethernet device 
(/org/freedesktop/NetworkManager/Devices/2)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5542] 
keyfile: add connection in-memory 
(82fc517c-d2f9-34d7-b457-6a76d13e294a,"Wired connection 1")
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5635] 
settings: (enp0s3): created default wired connection 'Wired connection 
1'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.5827] 
device (enp0s3): state change: unmanaged -> unavailable (reason 
'managed', internal state 'external')
Feb  5 10:16:51 localhost vmunix: [   11.031113] IPv6: 
ADDRCONF(NETDEV_UP): enp0s3: link is not ready
Feb  5 10:16:51 localhost vmunix: [   11.038770] IPv6: 
ADDRCONF(NETDEV_UP): enp0s3: link is not ready
Feb  5 10:16:51 localhost vmunix: [   11.042373] e1000: enp0s3 NIC Link 
is Up 1000 Mbps Full Duplex, Flow Control: RX
Feb  5 10:16:51 localhost vmunix: [   11.043277] IPv6: 
ADDRCONF(NETDEV_CHANGE): enp0s3: link becomes ready
Feb  5 10:16:51 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.PolicyKit1' requested by ':1.4' (uid=0 pid=353 
comm="/gnu/store/yccciw23f76dpfnm0f2d7kzxlb2h973c-networ") (using 
servicehelper)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6635] 
device (enp0s3): link connected
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6656] 
device (enp0s3): state change: unavailable -> disconnected (reason 
'carrier-changed', internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <warn>  [1549358211.6753] 
error poking ModemManager: 
GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name 
org.freedesktop.ModemManager1 was not provided by any .service files
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6758] 
policy: auto-activating connection 'Wired connection 1'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6899] 
device (enp0s3): Activation: starting connection 'Wired connection 1' 
(82fc517c-d2f9-34d7-b457-6a76d13e294a)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6906] 
device (enp0s3): state change: disconnected -> prepare (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6908] 
manager: NetworkManager state is now CONNECTING
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6914] 
device (enp0s3): state change: prepare -> config (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6927] 
device (enp0s3): state change: config -> ip-config (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.6956] 
dhcp4 (enp0s3): activation: beginning transaction (timeout in 45 
seconds)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.7144] 
dhcp4 (enp0s3): dhclient started with pid 400
Feb  5 10:16:51 localhost avahi-daemon[359]: Joining mDNS multicast 
group on interface enp0s3.IPv6 with address fe80::e882:9a4a:3a68:9d76.
Feb  5 10:16:51 localhost avahi-daemon[359]: New relevant interface 
enp0s3.IPv6 for mDNS.
Feb  5 10:16:51 localhost avahi-daemon[359]: Registering new address 
record for fe80::e882:9a4a:3a68:9d76 on enp0s3.*.
Feb  5 10:16:51 localhost polkitd[396]: Started polkitd version 0.115
Feb  5 10:16:51 localhost dhclient: DHCPREQUEST for 10.0.2.15 on enp0s3 
to 255.255.255.255 port 67
Feb  5 10:16:51 localhost dhclient: DHCPACK of 10.0.2.15 from 10.0.2.2
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8439] 
dhcp4 (enp0s3):   address 10.0.2.15
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8440] 
dhcp4 (enp0s3):   plen 24 (255.255.255.0)
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3):   gateway 10.0.2.2
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3):   lease time 86400
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3):   nameserver '172.16.0.26'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3):   nameserver '172.16.0.25'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3):   domain name 'oslo.geodata.no'
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8441] 
dhcp4 (enp0s3): state changed unknown -> bound
Feb  5 10:16:51 localhost avahi-daemon[359]: Joining mDNS multicast 
group on interface enp0s3.IPv4 with address 10.0.2.15.
Feb  5 10:16:51 localhost avahi-daemon[359]: New relevant interface 
enp0s3.IPv4 for mDNS.
Feb  5 10:16:51 localhost avahi-daemon[359]: Registering new address 
record for 10.0.2.15 on enp0s3.IPv4.
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8521] 
device (enp0s3): state change: ip-config -> ip-check (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8602] 
device (enp0s3): state change: ip-check -> secondaries (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8614] 
device (enp0s3): state change: secondaries -> activated (reason 'none', 
internal state 'managed')
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8630] 
manager: NetworkManager state is now CONNECTED_LOCAL
Feb  5 10:16:51 localhost dhclient: bound to 10.0.2.15 -- renewal in 
34812 seconds.
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8850] 
manager: NetworkManager state is now CONNECTED_SITE
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.8852] 
policy: set 'Wired connection 1' (enp0s3) as default for IPv4 routing 
and DNS
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.9000] 
device (enp0s3): Activation: successful, device activated.
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.9005] 
manager: startup complete
Feb  5 10:16:51 localhost nscd: 320 monitored file `/etc/resolv.conf` 
was moved into place, adding watch
Feb  5 10:16:51 localhost NetworkManager[353]: <info>  [1549358211.9031] 
manager: NetworkManager state is now CONNECTED_GLOBAL
Feb  5 10:16:52 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.PolicyKit1'
Feb  5 10:16:54 localhost ntpd[354]: Listen normally on 4 enp0s3 
10.0.2.15:123
Feb  5 10:16:54 localhost ntpd[354]: Listen normally on 5 enp0s3 
[fe80::e882:9a4a:3a68:9d76%2]:123
Feb  5 10:16:56 localhost shepherd[1]: Service dockerd could not be 
started.
Feb  5 10:16:56 localhost shepherd[1]: Service console-keymap has been 
started.
Feb  5 10:17:00 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gtk.vfs.Daemon' requested by ':1.2' 
(uid=1000 pid=442 
comm="/gnu/store/dlmbp3cx7qpvshswz726yp2kq13cizcm-gnome-")
Feb  5 10:17:00 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gtk.vfs.Daemon'
Feb  5 10:17:01 localhost vmunix: [   20.501520] fuse init (API version 
7.28)
Feb  5 10:17:01 localhost gnome-keyring-daemon[482]: couldn't access 
control socket: /run/user/1000/keyring/control: No such file or 
directory
Feb  5 10:17:01 localhost gnome-keyring-daemon[481]: couldn't access 
control socket: /run/user/1000/keyring/control: No such file or 
directory
Feb  5 10:17:01 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.a11y.Bus' requested by ':1.8' (uid=1000 
pid=489 comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:01 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.a11y.Bus'
Feb  5 10:17:02 localhost pulseaudio[510]: [pulseaudio] alsa-util.c: 
Disabling timer-based scheduling because running inside a VM.
Feb  5 10:17:02 localhost pulseaudio[510]: [pulseaudio] alsa-util.c: 
Disabling timer-based scheduling because running inside a VM.
Feb  5 10:17:02 localhost pulseaudio[510]: [alsa-sink-Intel ICH] 
alsa-sink.c: ALSA woke us up to write new data to the device, but there 
was actually nothing to write.
Feb  5 10:17:02 localhost pulseaudio[510]: [alsa-sink-Intel ICH] 
alsa-sink.c: Most likely this is a bug in the ALSA driver 
'snd_intel8x0'. Please report this issue to the ALSA developers.
Feb  5 10:17:02 localhost pulseaudio[510]: [alsa-sink-Intel ICH] 
alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent 
snd_pcm_avail() returned 0 or another value < min_avail.
Feb  5 10:17:03 localhost pulseaudio[510]: [pulseaudio] bluez5-util.c: 
GetManagedObjects() failed: org.freedesktop.DBus.Error.ServiceUnknown: 
The name org.bluez was not provided by any .service files
Feb  5 10:17:04 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gnome.Shell.CalendarServer' requested by 
':1.7' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:04 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activated service 'org.gnome.Shell.CalendarServer' failed: Process 
org.gnome.Shell.CalendarServer exited with status 1
Feb  5 10:17:04 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.Accounts' requested by ':1.11' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-") (using 
servicehelper)
Feb  5 10:17:04 localhost accounts-daemon[534]: started daemon version 
0.6.50
Feb  5 10:17:04 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.Accounts'
Feb  5 10:17:04 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.GeoClue2' requested by ':1.11' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-") (using 
servicehelper)
Feb  5 10:17:04 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='ca.desrt.dconf' requested by ':1.7' (uid=1000 
pid=489 comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:04 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'ca.desrt.dconf'
Feb  5 10:17:04 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.GeoClue2'
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gtk.vfs.UDisks2VolumeMonitor' requested by 
':1.7' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:05 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.UDisks2' requested by ':1.37' (uid=1000 pid=549 
comm="/gnu/store/dlz15s83xkf1bk9m8qx8r7f94xqnxkz7-gvfs-1") (using 
servicehelper)
Feb  5 10:17:05 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.UDisks2'
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gtk.vfs.UDisks2VolumeMonitor'
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gtk.vfs.GPhoto2VolumeMonitor' requested by 
':1.7' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gtk.vfs.GPhoto2VolumeMonitor'
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gtk.vfs.MTPVolumeMonitor' requested by 
':1.7' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:17:05 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gtk.vfs.MTPVolumeMonitor'
Feb  5 10:17:08 localhost dbus-daemon[350]: [system] Activating service 
name='org.freedesktop.ColorManager' requested by ':1.43' (uid=1000 
pid=585 comm="/gnu/store/97fg4ncq5f7d2ldx4qiyjkpcpvspl1ll-gnome-") 
(using servicehelper)
Feb  5 10:17:08 localhost colord: Using mapping database file 
/var/lib/colord/mapping.db
Feb  5 10:17:08 localhost colord: Using device database file 
/var/lib/colord/storage.db
Feb  5 10:17:08 localhost colord: loaded plugin libcd_plugin_scanner.so
Feb  5 10:17:08 localhost colord: loaded plugin libcd_plugin_sane.so
Feb  5 10:17:08 localhost colord: loaded plugin libcd_plugin_camera.so
Feb  5 10:17:08 localhost colord: Daemon ready for requests
Feb  5 10:17:08 localhost dbus-daemon[350]: [system] Successfully 
activated service 'org.freedesktop.ColorManager'
Feb  5 10:17:08 localhost colord: Profile added: 
icc-06b14b003d198ad249bbe13463e7c4e0
Feb  5 10:17:08 localhost colord: Profile added: 
icc-3b6c50986651e0a8a606a9189110b31e
Feb  5 10:17:09 localhost colord: Automatic metadata add 
icc-06b14b003d198ad249bbe13463e7c4e0 to xrandr-Undefined-VBOX 
monitor-70780800
Feb  5 10:17:09 localhost colord: Device added: xrandr-Undefined-VBOX 
monitor-70780800
Feb  5 10:18:50 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gnome.Terminal' requested by ':1.42' 
(uid=1000 pid=1014 
comm="/gnu/store/1119fvj0ys11389ybyvkazp02ywl7l8h-gnome-")
Feb  5 10:18:51 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gnome.Terminal'
Feb  5 10:19:44 localhost shepherd[1]: Service dockerd could not be 
started.
Feb  5 10:25:00 localhost vmunix: [  497.738320] usb 2-1: USB 
disconnect, device number 2
Feb  5 10:25:00 localhost vmunix: [  497.743558] sd 2:0:0:0: [sdb] 
Synchronizing SCSI cache
Feb  5 10:25:00 localhost vmunix: [  497.743777] sd 2:0:0:0: [sdb] 
Synchronize Cache(10) failed: Result: hostbyte=DID_NO_CONNECT 
driverbyte=DRIVER_OK
Feb  5 10:25:04 localhost vmunix: [  501.766506] usb 2-1: new SuperSpeed 
Gen 1 USB device number 3 using xhci_hcd
Feb  5 10:25:04 localhost vmunix: [  501.787826] usb 2-1: New USB device 
found, idVendor=0bc2, idProduct=ab2d, bcdDevice= 1.00
Feb  5 10:25:04 localhost vmunix: [  501.787830] usb 2-1: New USB device 
strings: Mfr=2, Product=3, SerialNumber=1
Feb  5 10:25:04 localhost vmunix: [  501.787832] usb 2-1: Product: Ultra 
Slim MT
Feb  5 10:25:04 localhost vmunix: [  501.787834] usb 2-1: Manufacturer: 
Seagate
Feb  5 10:25:04 localhost vmunix: [  501.787836] usb 2-1: SerialNumber: 
NA95GN93
Feb  5 10:25:04 localhost vmunix: [  501.798611] usb 2-1: USB controller 
0000:00:0c.0 does not support streams, which are required by the UAS 
driver.
Feb  5 10:25:04 localhost vmunix: [  501.798615] usb 2-1: Please try an 
other USB controller if you wish to use UAS.
Feb  5 10:25:04 localhost vmunix: [  501.798617] usb-storage 2-1:1.0: 
USB Mass Storage device detected
Feb  5 10:25:04 localhost vmunix: [  501.801157] scsi host2: usb-storage 
2-1:1.0
Feb  5 10:25:04 localhost mtp-probe: checking bus 2, device 3: 
"/sys/devices/pci0000:00/0000:00:0c.0/usb2/2-1"
Feb  5 10:25:04 localhost mtp-probe: bus: 2, device: 3 was not an MTP 
device
Feb  5 10:25:04 localhost mtp-probe: checking bus 2, device 3: 
"/sys/devices/pci0000:00/0000:00:0c.0/usb2/2-1"
Feb  5 10:25:04 localhost mtp-probe: bus: 2, device: 3 was not an MTP 
device
Feb  5 10:25:05 localhost vmunix: [  502.818935] scsi 2:0:0:0: 
Direct-Access     Seagate  Ultra Slim MT    0304 PQ: 0 ANSI: 6
Feb  5 10:25:05 localhost vmunix: [  502.819242] sd 2:0:0:0: Attached 
scsi generic sg1 type 0
Feb  5 10:25:05 localhost vmunix: [  502.823116] sd 2:0:0:0: [sdb] 
Spinning up disk...
Feb  5 10:25:07 localhost vmunix: [  503.865399] ..ready
Feb  5 10:25:07 localhost vmunix: [  504.902878] sd 2:0:0:0: [sdb] 
3907029167 512-byte logical blocks: (2.00 TB/1.82 TiB)
Feb  5 10:25:07 localhost vmunix: [  505.091798] sd 2:0:0:0: [sdb] Write 
Protect is off
Feb  5 10:25:07 localhost vmunix: [  505.092838] sd 2:0:0:0: [sdb] Write 
cache: enabled, read cache: enabled, doesn't support DPO or FUA
Feb  5 10:25:07 localhost vmunix: [  505.201622]  sdb: sdb1
Feb  5 10:25:07 localhost vmunix: [  505.223886] sd 2:0:0:0: [sdb] 
Attached SCSI disk
Feb  5 10:25:16 localhost vmunix: [  514.200281] NET: Registered 
protocol family 38
Feb  5 10:25:17 localhost vmunix: [  515.126966] EXT4-fs (dm-0): mounted 
filesystem with ordered data mode. Opts: (null)
Feb  5 10:25:17 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Activating service name='org.gnome.Shell.HotplugSniffer' requested by 
':1.7' (uid=1000 pid=489 
comm="/gnu/store/is5qsnj1n8rjfiwgsa21m2fxza61y13j-gnome-")
Feb  5 10:25:17 localhost dbus-daemon[452]: [session uid=1000 pid=450] 
Successfully activated service 'org.gnome.Shell.HotplugSniffer'
Feb  5 10:25:40 localhost ntpd[354]: kernel reports TIME_ERROR: 0x41: 
Clock Unsynchronized
Feb  5 10:36:51 localhost -- MARK --
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/hosts` was 
deleted, removing watch
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/hosts` was 
created, adding watch
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/hosts` was 
written to
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/services` was 
deleted, removing watch
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/services` was 
created, adding watch
Feb  5 10:55:01 localhost nscd: 320 monitored file `/etc/services` was 
written to
Feb  5 10:55:01 localhost NetworkManager[353]: <info>  [1549360501.7877] 
settings: hostname changed from (none) to "guixsd"
Feb  5 10:55:02 localhost shepherd[1]: Evaluating user expression (let* 
((services (map primitive-load (?))) # ?) ?).
Feb  5 10:55:03 localhost shepherd[1]: Service user-homes could not be 
started.
Feb  5 10:55:03 localhost shepherd[1]: Service term-auto could not be 
started.
Feb  5 10:55:03 localhost shepherd[1]: Service dockerd has been started.
Feb  5 10:55:03 localhost vmunix: [ 2301.432366] bridge: filtering via 
arp/ip/ip6tables is no longer available by default. Update your scripts 
to load br_netfilter if you need this.
Feb  5 10:55:03 localhost vmunix: [ 2301.434033] Bridge firewalling 
registered
Feb  5 10:55:04 localhost vmunix: [ 2302.168789] Initializing XFRM 
netlink socket
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.6193] 
manager: (docker0): new Bridge device 
(/org/freedesktop/NetworkManager/Devices/3)
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8436] 
device (docker0): state change: unmanaged -> unavailable (reason 
'connection-assumed', internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8457] 
keyfile: add connection in-memory 
(599906c3-5c6b-4e6b-be3f-83eea3fb862f,"docker0")
Feb  5 10:55:04 localhost avahi-daemon[359]: Joining mDNS multicast 
group on interface docker0.IPv4 with address 172.17.0.1.
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8484] 
device (docker0): state change: unavailable -> disconnected (reason 
'connection-assumed', internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8513] 
device (docker0): Activation: starting connection 'docker0' 
(599906c3-5c6b-4e6b-be3f-83eea3fb862f)
Feb  5 10:55:04 localhost vmunix: [ 2302.435597] IPv6: 
ADDRCONF(NETDEV_UP): docker0: link is not ready
Feb  5 10:55:04 localhost avahi-daemon[359]: New relevant interface 
docker0.IPv4 for mDNS.
Feb  5 10:55:04 localhost avahi-daemon[359]: Registering new address 
record for 172.17.0.1 on docker0.IPv4.
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8649] 
device (docker0): state change: disconnected -> prepare (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8670] 
device (docker0): state change: prepare -> config (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8676] 
device (docker0): state change: config -> ip-config (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <warn>  [1549360504.8814] 
arping[0x12f5780,3]: arping could not be found; no ARPs will be sent
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8814] 
device (docker0): state change: ip-config -> ip-check (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8818] 
device (docker0): state change: ip-check -> secondaries (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8821] 
device (docker0): state change: secondaries -> activated (reason 'none', 
internal state 'external')
Feb  5 10:55:04 localhost NetworkManager[353]: <info>  [1549360504.8961] 
device (docker0): Activation: successful, device activated.
Feb  5 10:55:07 localhost NetworkManager[353]: <warn>  [1549360507.4710] 
arping[0x12f5780,3]: arping could not be found; no ARPs will be sent
Feb  5 11:16:52 localhost -- MARK --




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 08 Feb 2019 21:56:01 GMT) Full text and rfc822 format available.

Message #8 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: allan <at> adair.io
Cc: 34333 <at> debbugs.gnu.org, Danny Milosavljevic <dannym <at> scratchpost.org>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 08 Feb 2019 22:55:48 +0100
Hello,

allan <at> adair.io skribis:

> Hi, I am having an issue with the docker daemon as a service in
> guixsd. It seems that dockerd will not start on boot, but it will
> successfully start after running "guix system reconfigure".

[...]

> After booting:
>
>
>
> allana <at> guixsd ~$ docker ps
> Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is
> the docker daemon running?
> allana <at> guixsd ~$ sudo herd status dockerd
> Password:
> Status of dockerd:
>   It is stopped.
>   It is enabled.

This is what happens at boot time:

> Feb  5 10:16:51 localhost shepherd[1]: Service containerd has been

[...]

> Feb  5 10:16:51 localhost NetworkManager[353]: <info>
> [1549358211.3005] NetworkManager (version 1.8.4) is starting... (for
> the first time)

[...]

> [1549358211.9031] manager: NetworkManager state is now
> CONNECTED_GLOBAL
> Feb  5 10:16:52 localhost dbus-daemon[350]: [system] Successfully
> activated service 'org.freedesktop.PolicyKit1'
> Feb  5 10:16:54 localhost ntpd[354]: Listen normally on 4 enp0s3
> 10.0.2.15:123
> Feb  5 10:16:54 localhost ntpd[354]: Listen normally on 5 enp0s3
> [fe80::e882:9a4a:3a68:9d76%2]:123
> Feb  5 10:16:56 localhost shepherd[1]: Service dockerd could not be
> started.

Danny, could it be that the ‘docker’ service should depend on
‘networking’?

FWIW, “make check-system TESTS=docker” passes for me.

Thanks,
Ludo’.




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 11 Feb 2019 10:47:02 GMT) Full text and rfc822 format available.

Message #11 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: allan <at> adair.io
Cc: 34333 <at> debbugs.gnu.org, Ludovic Courtès <ludo <at> gnu.org>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 11 Feb 2019 11:46:51 +0100
[Message part 1 (text/plain, inline)]
On Fri, 08 Feb 2019 22:55:48 +0100
Ludovic Courtès <ludo <at> gnu.org> wrote:

> Danny, could it be that the ‘docker’ service should depend on
> ‘networking’?

Might be the case.  They certainly muck around a lot with networking,
so it can't hurt to wait until host networking is set up.

I've added it--let's see.

Allan, can you guix pull and guix reconfigure and then try again?
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 11 Feb 2019 13:12:01 GMT) Full text and rfc822 format available.

Message #14 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 34333 <at> debbugs.gnu.org, Ludovic Courtès <ludo <at> gnu.org>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 11 Feb 2019 13:11:33 +0000
On 2019-02-11 10:46, Danny Milosavljevic wrote:
> On Fri, 08 Feb 2019 22:55:48 +0100
> Ludovic Courtès <ludo <at> gnu.org> wrote:
> 
>> Danny, could it be that the ‘docker’ service should depend on
>> ‘networking’?
> 
> Might be the case.  They certainly muck around a lot with networking,
> so it can't hurt to wait until host networking is set up.
> 
> I've added it--let's see.
> 
> Allan, can you guix pull and guix reconfigure and then try again?

I guix pulled and guix system reconfigured. After a successful 
reconfigure and reboot, the service was still not started.

-- 
Allan Adair
+47 468 12 135
allan <at> adair.io
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 11 Feb 2019 14:25:02 GMT) Full text and rfc822 format available.

Message #17 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: 34333 <at> debbugs.gnu.org, Ludovic Courtès <ludo <at> gnu.org>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 11 Feb 2019 15:24:05 +0100
[Message part 1 (text/plain, inline)]
On Mon, 11 Feb 2019 13:11:33 +0000
Allan Adair <allan <at> adair.io> wrote:

> I guix pulled and guix system reconfigured. After a successful 
> reconfigure and reboot, the service was still not started.

Hmm, is the "containerd" process running? (pidof containerd)
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 11 Feb 2019 17:33:02 GMT) Full text and rfc822 format available.

Message #20 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: allan <at> adair.io
Cc: 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 11 Feb 2019 18:31:55 +0100
[Message part 1 (text/plain, inline)]
Hi Allan,

I've added some more requirements--let's see.

Can you guix pull and guix reconfigure and then try again once more?
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Tue, 12 Feb 2019 09:06:02 GMT) Full text and rfc822 format available.

Message #23 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Tue, 12 Feb 2019 09:05:10 +0000
On 2019-02-11 17:31, Danny Milosavljevic wrote:
> Hi Allan,
> 
> I've added some more requirements--let's see.
> 
> Can you guix pull and guix reconfigure and then try again once more?

Still no luck. Do you face the same issue?

-- 
Allan Adair
+47 468 12 135
allan <at> adair.io
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Tue, 12 Feb 2019 17:46:01 GMT) Full text and rfc822 format available.

Message #26 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Tue, 12 Feb 2019 18:45:17 +0100
[Message part 1 (text/plain, inline)]
Hi Allan,

On Tue, 12 Feb 2019 09:05:10 +0000
Allan Adair <allan <at> adair.io> wrote:

> On 2019-02-11 17:31, Danny Milosavljevic wrote:
> > Hi Allan,
> > 
> > I've added some more requirements--let's see.
> > 
> > Can you guix pull and guix reconfigure and then try again once more?  
> 
> Still no luck. Do you face the same issue?

I don't know since my machine has not finished updating after the
recent staging to master merge.
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Wed, 27 Feb 2019 14:47:01 GMT) Full text and rfc822 format available.

Message #29 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Wed, 27 Feb 2019 15:17:14 +0100
Hey Danny.

I'm curious to know if the dockerd service type works for you. It does
not work for me, but maybe I am doing something wrong. Below is my
current config.scm:

(use-modules (gnu)
             (gnu system nss)
	     (gnu services))
(use-service-modules desktop docker)
(use-package-modules certs gnome)

(operating-system
 (host-name "guixsd")
 (timezone "Europe/Oslo")
 (locale "en_US.utf8")

  (bootloader (bootloader-configuration
               (bootloader grub-bootloader)
               (target "/dev/sda")))

  (file-systems (cons (file-system
		       (device (file-system-label "my-root"))
		       (mount-point "/")
		       (type "ext4"))
                      %base-file-systems))

  (users (cons (user-account
                (name "allana")
                (group "users")
                (supplementary-groups '("wheel"
					"docker"
					"netdev"
                                        "audio"
					"video"))
                (home-directory "/home/allana"))
               %base-user-accounts))

  ;; This is where we specify system-wide packages.
  (packages (cons* nss-certs         ;for HTTPS access
                   gvfs              ;for user mounts
                   %base-packages))

  (services (cons* (console-keymap-service "no-latin1")
                   (gnome-desktop-service)
		   (service docker-service-type)
                   %desktop-services))

  ;; Allow resolution of '.local' host names with mDNS.
  (name-service-switch %mdns-host-lookup-nss))


After a "guix system reconfigure", it works -- meaning that the dockerd
service starts. But when booting in the future, the dockerd
daemon never starts. I am however able to execute "sudo herd start
dockerd" after booting because I have included dockerd in my user
profile.  I can also "guix system reconfigure" at this point to start
the dockerd service, but then at the next boot it will still not start.


Danny Milosavljevic writes:

> Hi Allan,
>
> On Tue, 12 Feb 2019 09:05:10 +0000
> Allan Adair <allan <at> adair.io> wrote:
>
>> On 2019-02-11 17:31, Danny Milosavljevic wrote:
>> > Hi Allan,
>> > 
>> > I've added some more requirements--let's see.
>> > 
>> > Can you guix pull and guix reconfigure and then try again once more?  
>> 
>> Still no luck. Do you face the same issue?
>
> I don't know since my machine has not finished updating after the
> recent staging to master merge.


-- 
Allan Adair
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Wed, 27 Feb 2019 15:54:01 GMT) Full text and rfc822 format available.

Message #32 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>
To: Allan Adair <allan <at> adair.io>
Cc: Danny Milosavljevic <dannym <at> scratchpost.org>, 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Wed, 27 Feb 2019 16:53:27 +0100
[Message part 1 (text/plain, inline)]
On Wed, 27 Feb 2019 15:17:14 +0100
Allan Adair <allan <at> adair.io> wrote:


> After a "guix system reconfigure", it works -- meaning that the
> dockerd service starts. But when booting in the future, the dockerd
> daemon never starts. I am however able to execute "sudo herd start
> dockerd" after booting because I have included dockerd in my user
> profile.  I can also "guix system reconfigure" at this point to start
> the dockerd service, but then at the next boot it will still not
> start.

I can confirm this behaviour, though I haven't yet investigated it
further.

Björn
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Wed, 27 Feb 2019 16:32:01 GMT) Full text and rfc822 format available.

Message #35 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Andreas Enge <andreas <at> enge.fr>
To: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>
Cc: 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Wed, 27 Feb 2019 17:31:21 +0100
On Wed, Feb 27, 2019 at 04:53:27PM +0100, Björn Höfling wrote:
> > After a "guix system reconfigure", it works -- meaning that the
> > dockerd service starts. But when booting in the future, the dockerd
> > daemon never starts. I am however able to execute "sudo herd start
> > dockerd" after booting because I have included dockerd in my user
> > profile.  I can also "guix system reconfigure" at this point to start
> > the dockerd service, but then at the next boot it will still not
> > start.
> 
> I can confirm this behaviour, though I haven't yet investigated it
> further.

Could this be yet another manifestation of
   https://debbugs.gnu.org/cgi/bugreport.cgi?bug=34580 ?
Services not started on boot?

Andreas





Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 01 Mar 2019 09:00:02 GMT) Full text and rfc822 format available.

Message #38 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Andreas Enge <andreas <at> enge.fr>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 01 Mar 2019 09:58:20 +0100
Andreas Enge writes:

> On Wed, Feb 27, 2019 at 04:53:27PM +0100, Björn Höfling wrote:
>> > After a "guix system reconfigure", it works -- meaning that the
>> > dockerd service starts. But when booting in the future, the dockerd
>> > daemon never starts. I am however able to execute "sudo herd start
>> > dockerd" after booting because I have included dockerd in my user
>> > profile.  I can also "guix system reconfigure" at this point to start
>> > the dockerd service, but then at the next boot it will still not
>> > start.
>> 
>> I can confirm this behaviour, though I haven't yet investigated it
>> further.
>
> Could this be yet another manifestation of
>    https://debbugs.gnu.org/cgi/bugreport.cgi?bug=34580 ?
> Services not started on boot?
>
> Andreas

I'm not so sure. One thing that I am unable to do is "herd start
dockerd".

-- 
Allan Adair
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 01 Mar 2019 13:10:02 GMT) Full text and rfc822 format available.

Message #41 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Andreas Enge <andreas <at> enge.fr>
To: Allan Adair <allan <at> adair.io>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 1 Mar 2019 14:09:32 +0100
On Fri, Mar 01, 2019 at 09:58:20AM +0100, Allan Adair wrote:
> >> > I am however able to execute "sudo herd start
> >> > dockerd" after booting
> 
> I'm not so sure. One thing that I am unable to do is "herd start
> dockerd".

You mean, you are not able to start it via
    sudo su -
    herd start dockerd
?

It is normal that you cannot start services as a normal user.

Andreas





Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 01 Mar 2019 13:44:02 GMT) Full text and rfc822 format available.

Message #44 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 1 Mar 2019 14:43:24 +0100
[Message part 1 (text/plain, inline)]
On Fri, 1 Mar 2019 14:09:32 +0100
Andreas Enge <andreas <at> enge.fr> wrote:

> On Fri, Mar 01, 2019 at 09:58:20AM +0100, Allan Adair wrote:
> > >> > I am however able to execute "sudo herd start
> > >> > dockerd" after booting  
> > 
> > I'm not so sure. One thing that I am unable to do is "herd start
> > dockerd".  
> 
> You mean, you are not able to start it via
>     sudo su -
>     herd start dockerd
> ?
> 
> It is normal that you cannot start services as a normal user.

I wondered about that too.

For me, a "sudo herd start dockerd" works. After that, I can use the
docker-cli tools to work with docker images and containers. They deploy
and run fine.

Björn

[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 01 Mar 2019 13:51:01 GMT) Full text and rfc822 format available.

Message #47 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>
Cc: 34333 <at> debbugs.gnu.org, Andreas Enge <andreas <at> enge.fr>,
 Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 01 Mar 2019 14:50:39 +0100
Björn Höfling writes:

> On Fri, 1 Mar 2019 14:09:32 +0100
> Andreas Enge <andreas <at> enge.fr> wrote:
>
>> On Fri, Mar 01, 2019 at 09:58:20AM +0100, Allan Adair wrote:
>> > >> > I am however able to execute "sudo herd start
>> > >> > dockerd" after booting  
>> > 
>> > I'm not so sure. One thing that I am unable to do is "herd start
>> > dockerd".  
>> 
>> You mean, you are not able to start it via
>>     sudo su -
>>     herd start dockerd
>> ?
>> 
>> It is normal that you cannot start services as a normal user.
>
> I wondered about that too.
>
> For me, a "sudo herd start dockerd" works. After that, I can use the
> docker-cli tools to work with docker images and containers. They deploy
> and run fine.
>
> Björn

After a fresh boot:

allana <at> guixsd ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
allana <at> guixsd ~$ sudo herd status dockerd
Password: 
Status of dockerd:
  It is stopped.
  It is enabled.
  Provides (dockerd).
  Requires (containerd dbus-system elogind file-system-/sys/fs/cgroup/blkio file-system-/sys/fs/cgroup/cpu file-system-/sys/fs/cgroup/cpuset file-system-/sys/fs/cgroup/devices file-system-/sys/fs/cgroup/memory networking udev).
  Conflicts with ().
  Will be respawned.
allana <at> guixsd ~$ sudo herd start dockerd
Service dockerd could not be started.
herd: failed to start service dockerd


-- 
Allan Adair
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Fri, 01 Mar 2019 18:02:01 GMT) Full text and rfc822 format available.

Message #50 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Fri, 1 Mar 2019 19:00:06 +0100
[Message part 1 (text/plain, inline)]
Hi,

On Fri, 01 Mar 2019 14:50:39 +0100
Allan Adair <allan <at> adair.io> wrote:

> After a fresh boot:
> 
> allana <at> guixsd ~$ docker ps
> Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
> allana <at> guixsd ~$ sudo herd status dockerd
> Password: 
> Status of dockerd:
>   It is stopped.
>   It is enabled.
>   Provides (dockerd).
>   Requires (containerd dbus-system elogind file-system-/sys/fs/cgroup/blkio file-system-/sys/fs/cgroup/cpu file-system-/sys/fs/cgroup/cpuset file-system-/sys/fs/cgroup/devices file-system-/sys/fs/cgroup/memory networking udev).
>   Conflicts with ().
>   Will be respawned.
> allana <at> guixsd ~$ sudo herd start dockerd
> Service dockerd could not be started.
> herd: failed to start service dockerd

In a way that's good that this failure is reproducible so well.

"herd start dockerd" would do:

$(guix build docker)/bin/dockerd -p /var/run/docker.pid

For debugging, can you please try invoking the latter instead
of "herd start dockerd" ?

After that, please try

$(guix build docker)/bin/dockerd -p /var/run/docker.pid -D


[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 11 Mar 2019 09:00:02 GMT) Full text and rfc822 format available.

Message #53 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 11 Mar 2019 09:59:19 +0100
Hi Danny.

Sorry for the late response. I was offline for the last week or so.

I ended up having to repeat the first command with sudo
privileges. Please see below.

Danny Milosavljevic writes:

> Hi,
>
> On Fri, 01 Mar 2019 14:50:39 +0100
> Allan Adair <allan <at> adair.io> wrote:
>
>> After a fresh boot:
>> 
>> allana <at> guixsd ~$ docker ps
>> Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
>> allana <at> guixsd ~$ sudo herd status dockerd
>> Password: 
>> Status of dockerd:
>>   It is stopped.
>>   It is enabled.
>>   Provides (dockerd).
>>   Requires (containerd dbus-system elogind file-system-/sys/fs/cgroup/blkio file-system-/sys/fs/cgroup/cpu file-system-/sys/fs/cgroup/cpuset file-system-/sys/fs/cgroup/devices file-system-/sys/fs/cgroup/memory networking udev).
>>   Conflicts with ().
>>   Will be respawned.
>> allana <at> guixsd ~$ sudo herd start dockerd
>> Service dockerd could not be started.
>> herd: failed to start service dockerd
>
> In a way that's good that this failure is reproducible so well.
>
> "herd start dockerd" would do:
>
> $(guix build docker)/bin/dockerd -p /var/run/docker.pid
>
> For debugging, can you please try invoking the latter instead
> of "herd start dockerd" ?
>
> After that, please try
>
> $(guix build docker)/bin/dockerd -p /var/run/docker.pid -D

allana <at> guixsd ~$ $(guix build docker)/bin/dockerd -p /var/run/docker.pid
substitute: updating substitutes from 'https://ci.guix.info'... 100.0%
substitute: updating substitutes from 'https://ci.guix.info'... 100.0%
substitute: updating substitutes from 'https://ci.guix.info'... 100.0%
substitute: updating substitutes from 'https://ci.guix.info'... 100.0%
93.1 MB will be downloaded:
   /gnu/store/fqzdfac28a7h0wsxz6wdgjym491klbqh-docker-18.09.2
   /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2
   /gnu/store/cqd3yimzpj0r29l3dyh8xcqbx70cbanc-xfsprogs-4.20.0
   /gnu/store/hz2mq9wpddaifn2sij5msswhzzf8136b-iproute2-4.20.0
   /gnu/store/pg3jsf0sp6p66lr6r0bfyz1lx2n6jb2b-containerd-1.2.4
The following graft will be made:
   /gnu/store/a9frz994s0qiq6iay6yhfii8swvz6yyp-docker-18.09.2.drv
substituting /gnu/store/pg3jsf0sp6p66lr6r0bfyz1lx2n6jb2b-containerd-1.2.4...
downloading from https://ci.guix.info/nar/gzip/pg3jsf0sp6p66lr6r0bfyz1lx2n6jb2b-containerd-1.2.4...
 containerd-1.2.4  35.5MiB            1.5MiB/s 00:23 [##################] 100.0%

substituting /gnu/store/y3zh0rhc25vakfl4q49sxs8kzcqm8bhi-libnftnl-1.1.2...
downloading from https://ci.guix.info/nar/gzip/y3zh0rhc25vakfl4q49sxs8kzcqm8bhi-libnftnl-1.1.2...
 libnftnl-1.1.2  85KiB                1.8MiB/s 00:00 [##################] 100.0%

substituting /gnu/store/cqd3yimzpj0r29l3dyh8xcqbx70cbanc-xfsprogs-4.20.0...
downloading from https://ci.guix.info/nar/gzip/cqd3yimzpj0r29l3dyh8xcqbx70cbanc-xfsprogs-4.20.0...
 xfsprogs-4.20.0  2.3MiB              1.4MiB/s 00:02 [##################] 100.0%

substituting /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2...
downloading from https://ci.guix.info/nar/gzip/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2...
 iptables-1.6.2  555KiB               2.4MiB/s 00:00 [##################] 100.0%

substituting /gnu/store/hz2mq9wpddaifn2sij5msswhzzf8136b-iproute2-4.20.0...
downloading from https://ci.guix.info/nar/gzip/hz2mq9wpddaifn2sij5msswhzzf8136b-iproute2-4.20.0...
 iproute2-4.20.0  1.0MiB              3.3MiB/s 00:00 [##################] 100.0%

substituting /gnu/store/fqzdfac28a7h0wsxz6wdgjym491klbqh-docker-18.09.2...
downloading from https://ci.guix.info/nar/gzip/fqzdfac28a7h0wsxz6wdgjym491klbqh-docker-18.09.2...
 docker-18.09.2  49.5MiB              1.5MiB/s 00:33 [##################] 100.0%

applying 1 graft for /gnu/store/a9frz994s0qiq6iay6yhfii8swvz6yyp-docker-18.09.2.drv...
grafting '/gnu/store/fqzdfac28a7h0wsxz6wdgjym491klbqh-docker-18.09.2' -> '/gnu/store/2vf8f8bky5jlifghqgl92n7a3vx6icid-docker-18.09.2'...
successfully built /gnu/store/a9frz994s0qiq6iay6yhfii8swvz6yyp-docker-18.09.2.drv
chmod /var/lib/docker: operation not permitted
allana <at> guixsd ~$ sudo $(guix build docker)/bin/dockerd -p /var/run/docker.pid
Password: 
INFO[2019-03-11T09:55:18.870049018+01:00] parsed scheme: "unix"                         module=grpc
INFO[2019-03-11T09:55:18.870157978+01:00] scheme "unix" not registered, fallback to default scheme  module=grpc
INFO[2019-03-11T09:55:18.870220789+01:00] parsed scheme: "unix"                         module=grpc
INFO[2019-03-11T09:55:18.870263818+01:00] scheme "unix" not registered, fallback to default scheme  module=grpc
INFO[2019-03-11T09:55:18.870988104+01:00] ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]  module=grpc
INFO[2019-03-11T09:55:18.871011336+01:00] ClientConn switching balancer to "pick_first"  module=grpc
INFO[2019-03-11T09:55:18.871121368+01:00] ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]  module=grpc
INFO[2019-03-11T09:55:18.871135562+01:00] ClientConn switching balancer to "pick_first"  module=grpc
INFO[2019-03-11T09:55:18.871191852+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc00094bd80, CONNECTING  module=grpc
INFO[2019-03-11T09:55:18.871490772+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc00094bd80, READY  module=grpc
INFO[2019-03-11T09:55:18.872052533+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc0007aa120, CONNECTING  module=grpc
INFO[2019-03-11T09:55:18.872637966+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc0007aa120, READY  module=grpc
INFO[2019-03-11T09:55:18.956930716+01:00] [graphdriver] using prior storage driver: overlay2 
INFO[2019-03-11T09:55:19.446624398+01:00] Graph migration to content-addressability took 0.00 seconds 
WARN[2019-03-11T09:55:19.446793841+01:00] Your kernel does not support swap memory limit 
WARN[2019-03-11T09:55:19.446839108+01:00] Your kernel does not support cgroup rt period 
WARN[2019-03-11T09:55:19.446851151+01:00] Your kernel does not support cgroup rt runtime 
WARN[2019-03-11T09:55:19.446944180+01:00] mountpoint for pids not found                
INFO[2019-03-11T09:55:19.447094857+01:00] Loading containers: start.                   
INFO[2019-03-11T09:55:19.806237867+01:00] Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address 
INFO[2019-03-11T09:55:19.879444062+01:00] Loading containers: done.                    
WARN[2019-03-11T09:55:19.879977264+01:00] Could not get operating system name: Error opening /usr/lib/os-release: open /usr/lib/os-release: no such file or directory 
WARN[2019-03-11T09:55:19.959765663+01:00] failed to retrieve /gnu/store/l6nqfq4vyzaxjk8xygm4vr203p04430g-runc-1.0.0-rc6/sbin/runc version: unknown output format: runc version 1.0.0-rc6
spec: 1.0.1-dev
 
WARN[2019-03-11T09:55:19.960225775+01:00] failed to retrieve docker-init version: exec: "docker-init": executable file not found in $PATH 
INFO[2019-03-11T09:55:20.010894492+01:00] Docker daemon                                 commit=v18.09.2 graphdriver(s)=overlay2 version=dev
INFO[2019-03-11T09:55:20.011355589+01:00] Daemon has completed initialization          
INFO[2019-03-11T09:55:20.047488136+01:00] API listen on /var/run/docker.sock           
^CINFO[2019-03-11T09:55:37.423979436+01:00] Processing signal 'interrupt'                
INFO[2019-03-11T09:55:37.424612060+01:00] stopping event stream following graceful shutdown  error="<nil>" module=libcontainerd namespace=moby
allana <at> guixsd ~$ sudo $(guix build docker)/bin/dockerd -p /var/run/docker.pid -D
DEBU[2019-03-11T09:56:04.702178848+01:00] Listener created for HTTP on unix (/var/run/docker.sock) 
DEBU[2019-03-11T09:56:04.705370926+01:00] Golang's threads limit set to 42750          
INFO[2019-03-11T09:56:04.705630548+01:00] parsed scheme: "unix"                         module=grpc
INFO[2019-03-11T09:56:04.705647118+01:00] scheme "unix" not registered, fallback to default scheme  module=grpc
INFO[2019-03-11T09:56:04.705671668+01:00] parsed scheme: "unix"                         module=grpc
INFO[2019-03-11T09:56:04.705728970+01:00] scheme "unix" not registered, fallback to default scheme  module=grpc
DEBU[2019-03-11T09:56:04.705848912+01:00] Using default logging driver json-file       
DEBU[2019-03-11T09:56:04.705997733+01:00] [graphdriver] priority list: [btrfs zfs overlay2 aufs overlay devicemapper vfs] 
INFO[2019-03-11T09:56:04.706176881+01:00] ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]  module=grpc
INFO[2019-03-11T09:56:04.706204607+01:00] ClientConn switching balancer to "pick_first"  module=grpc
INFO[2019-03-11T09:56:04.706358229+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc000476fa0, CONNECTING  module=grpc
INFO[2019-03-11T09:56:04.706883252+01:00] ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]  module=grpc
INFO[2019-03-11T09:56:04.706955511+01:00] ClientConn switching balancer to "pick_first"  module=grpc
INFO[2019-03-11T09:56:04.707033402+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc00012f890, CONNECTING  module=grpc
INFO[2019-03-11T09:56:04.707276723+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc00012f890, READY  module=grpc
DEBU[2019-03-11T09:56:04.707364455+01:00] processing event stream                       module=libcontainerd namespace=plugins.moby
INFO[2019-03-11T09:56:04.707645989+01:00] pickfirstBalancer: HandleSubConnStateChange: 0xc000476fa0, READY  module=grpc
DEBU[2019-03-11T09:56:04.709345382+01:00] backingFs=extfs, projectQuotaSupported=false, indexOff="index=off,"  storage-driver=overlay2
INFO[2019-03-11T09:56:04.709365553+01:00] [graphdriver] using prior storage driver: overlay2 
DEBU[2019-03-11T09:56:04.709375543+01:00] Initialized graph driver overlay2            
INFO[2019-03-11T09:56:04.869373608+01:00] Graph migration to content-addressability took 0.00 seconds 
WARN[2019-03-11T09:56:04.869724040+01:00] Your kernel does not support swap memory limit 
WARN[2019-03-11T09:56:04.869848963+01:00] Your kernel does not support cgroup rt period 
WARN[2019-03-11T09:56:04.869913102+01:00] Your kernel does not support cgroup rt runtime 
WARN[2019-03-11T09:56:04.870102948+01:00] mountpoint for pids not found                
DEBU[2019-03-11T09:56:04.870502775+01:00] Max Concurrent Downloads: 3                  
DEBU[2019-03-11T09:56:04.870602223+01:00] Max Concurrent Uploads: 5                    
INFO[2019-03-11T09:56:04.870689021+01:00] Loading containers: start.                   
DEBU[2019-03-11T09:56:04.870793282+01:00] processing event stream                       module=libcontainerd namespace=moby
DEBU[2019-03-11T09:56:04.872062033+01:00] Loaded container 3299a646cd8ce704ac633a8abc327c0b725091a6ad7a8a9aebb115b5c8da3dfb, isRunning: false 
DEBU[2019-03-11T09:56:04.872517168+01:00] Loaded container 4823ba5ae65285c6820904400dd9ee266c215de2ee4bb8feb2ffd171decbc3a8, isRunning: false 
DEBU[2019-03-11T09:56:04.872936548+01:00] Loaded container 91db42839d8c3af7d4a839b4857d5a5f2cd2ef281439441b9a3dbd8d75c58d23, isRunning: false 
DEBU[2019-03-11T09:56:04.873289969+01:00] Loaded container 9a3a0a12f5b253b4f6bc033dd5742c59d916be86d453b01b4fb9bd1f748c6109, isRunning: false 
DEBU[2019-03-11T09:56:04.873710129+01:00] Loaded container b5c9f1544e61a6c3d5352e4c17627a078962dc94db80c10f401daa2b1b1f04f7, isRunning: false 
DEBU[2019-03-11T09:56:04.874190948+01:00] Loaded container b9492761f66d0b43f183539b2f4d81bde8062380265d12e99e62f466d16cef37, isRunning: false 
DEBU[2019-03-11T09:56:04.874801472+01:00] Loaded container c03032427b791f5c7f2ee05f305a3732dcc40e6c60738152dd3dcca20ac567dd, isRunning: false 
DEBU[2019-03-11T09:56:04.875312431+01:00] Loaded container d6de99424c3b1ebf55dd2442f2826cbca46ce0c9d691ee625fb69264d1ac2671, isRunning: false 
DEBU[2019-03-11T09:56:04.875981166+01:00] Loaded container f06e122ebd9b3743af1731ccb1414f6a2dbd14819c7686b17ec7f9ded58f2ea0, isRunning: false 
DEBU[2019-03-11T09:56:04.927687231+01:00] restoring container                           container=b5c9f1544e61a6c3d5352e4c17627a078962dc94db80c10f401daa2b1b1f04f7 paused=false running=false
DEBU[2019-03-11T09:56:04.928733975+01:00] restoring container                           container=91db42839d8c3af7d4a839b4857d5a5f2cd2ef281439441b9a3dbd8d75c58d23 paused=false running=false
DEBU[2019-03-11T09:56:04.931705005+01:00] restoring container                           container=9a3a0a12f5b253b4f6bc033dd5742c59d916be86d453b01b4fb9bd1f748c6109 paused=false running=false
DEBU[2019-03-11T09:56:04.933856231+01:00] restoring container                           container=b9492761f66d0b43f183539b2f4d81bde8062380265d12e99e62f466d16cef37 paused=false running=false
DEBU[2019-03-11T09:56:04.934503968+01:00] restoring container                           container=c03032427b791f5c7f2ee05f305a3732dcc40e6c60738152dd3dcca20ac567dd paused=false running=false
DEBU[2019-03-11T09:56:04.937068955+01:00] restoring container                           container=f06e122ebd9b3743af1731ccb1414f6a2dbd14819c7686b17ec7f9ded58f2ea0 paused=false running=false
DEBU[2019-03-11T09:56:04.942464745+01:00] restoring container                           container=3299a646cd8ce704ac633a8abc327c0b725091a6ad7a8a9aebb115b5c8da3dfb paused=false running=false
DEBU[2019-03-11T09:56:04.948944968+01:00] restoring container                           container=d6de99424c3b1ebf55dd2442f2826cbca46ce0c9d691ee625fb69264d1ac2671 paused=false running=false
DEBU[2019-03-11T09:56:04.950749457+01:00] restoring container                           container=4823ba5ae65285c6820904400dd9ee266c215de2ee4bb8feb2ffd171decbc3a8 paused=false running=false
DEBU[2019-03-11T09:56:04.951138869+01:00] Option Experimental: false                   
DEBU[2019-03-11T09:56:04.951152892+01:00] Option DefaultDriver: bridge                 
DEBU[2019-03-11T09:56:04.951158162+01:00] Option DefaultNetwork: bridge                
DEBU[2019-03-11T09:56:04.951194917+01:00] Network Control Plane MTU: 1500              
DEBU[2019-03-11T09:56:04.959536156+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-ISOLATION] 
DEBU[2019-03-11T09:56:04.960569108+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:04.961665409+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER] 
DEBU[2019-03-11T09:56:04.962715498+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:04.966849058+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D PREROUTING] 
DEBU[2019-03-11T09:56:04.968037631+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D OUTPUT] 
DEBU[2019-03-11T09:56:04.969116145+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -F DOCKER] 
DEBU[2019-03-11T09:56:04.970012713+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -X DOCKER] 
DEBU[2019-03-11T09:56:04.970911109+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -F DOCKER] 
DEBU[2019-03-11T09:56:04.972030220+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -X DOCKER] 
DEBU[2019-03-11T09:56:04.972975967+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -F DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:04.974045262+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -X DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:04.974939961+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -F DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:04.976123301+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -X DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:04.977345385+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -F DOCKER-ISOLATION] 
DEBU[2019-03-11T09:56:04.993484633+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -X DOCKER-ISOLATION] 
DEBU[2019-03-11T09:56:04.995181775+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -n -L DOCKER] 
DEBU[2019-03-11T09:56:04.999757355+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -N DOCKER] 
DEBU[2019-03-11T09:56:05.003280086+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -n -L DOCKER] 
DEBU[2019-03-11T09:56:05.004359235+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -n -L DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.005306171+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -n -L DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.011943772+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -N DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.016422142+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-1 -j RETURN] 
DEBU[2019-03-11T09:56:05.017549657+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -A DOCKER-ISOLATION-STAGE-1 -j RETURN] 
DEBU[2019-03-11T09:56:05.018632139+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-2 -j RETURN] 
DEBU[2019-03-11T09:56:05.019744902+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -A DOCKER-ISOLATION-STAGE-2 -j RETURN] 
DEBU[2019-03-11T09:56:05.024866513+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE] 
DEBU[2019-03-11T09:56:05.025760898+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.026629780+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -I DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.027509122+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -i docker0 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.028412371+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.029256644+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.030148988+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:05.033882184+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:05.034894476+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8] 
DEBU[2019-03-11T09:56:05.035926698+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -A OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8] 
DEBU[2019-03-11T09:56:05.036877981+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.039792718+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.040859429+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.047794509+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.049226971+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.050449463+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.051363751+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.052266252+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.053132407+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -I DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.053985383+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.054843200+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -I DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.055860619+01:00] Network (fc0c79f) restored                   
DEBU[2019-03-11T09:56:05.056667771+01:00] Allocating IPv4 pools for network bridge (fc0c79f3077bdfc4591c9436bf25a63668ce8961b9a4f9c98c7bfffa3d5b64ae) 
DEBU[2019-03-11T09:56:05.056692562+01:00] RequestPool(LocalDefault, 172.17.0.0/16, , map[], false) 
DEBU[2019-03-11T09:56:05.056717170+01:00] RequestAddress(LocalDefault/172.17.0.0/16, 172.17.0.1, map[RequestAddressType:com.docker.network.gateway]) 
DEBU[2019-03-11T09:56:05.056735157+01:00] Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:172.17.0.1  
DEBU[2019-03-11T09:56:05.061383675+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE] 
DEBU[2019-03-11T09:56:05.066264415+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE] 
DEBU[2019-03-11T09:56:05.067406630+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.068682521+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -D DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.079741812+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.081703363+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -i docker0 -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.083899704+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.085111824+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -i docker0 ! -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.086383289+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.090421950+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.092871348+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.093983550+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.095048444+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.096757981+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.104180706+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.105653091+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -D DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.106740616+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.107648681+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -D DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.112100198+01:00] releasing IPv4 pools from network bridge (fc0c79f3077bdfc4591c9436bf25a63668ce8961b9a4f9c98c7bfffa3d5b64ae) 
DEBU[2019-03-11T09:56:05.112124776+01:00] ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.1) 
DEBU[2019-03-11T09:56:05.112165328+01:00] Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.1 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 
DEBU[2019-03-11T09:56:05.112177220+01:00] ReleasePool(LocalDefault/172.17.0.0/16)      
DEBU[2019-03-11T09:56:05.113131674+01:00] cleanupServiceDiscovery for network:fc0c79f3077bdfc4591c9436bf25a63668ce8961b9a4f9c98c7bfffa3d5b64ae 
INFO[2019-03-11T09:56:05.116621811+01:00] Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address 
DEBU[2019-03-11T09:56:05.116670253+01:00] Allocating IPv4 pools for network bridge (0e4a0a76c4327334b79e6fc5120f1e27fe76d4ff937f2d65452edb40d031aef6) 
DEBU[2019-03-11T09:56:05.116685066+01:00] RequestPool(LocalDefault, 172.17.0.0/16, , map[], false) 
DEBU[2019-03-11T09:56:05.116731043+01:00] RequestAddress(LocalDefault/172.17.0.0/16, 172.17.0.1, map[RequestAddressType:com.docker.network.gateway]) 
DEBU[2019-03-11T09:56:05.116754437+01:00] Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:172.17.0.1  
DEBU[2019-03-11T09:56:05.116896722+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE] 
DEBU[2019-03-11T09:56:05.118093964+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -I POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE] 
DEBU[2019-03-11T09:56:05.120892409+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.123980225+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -I DOCKER -i docker0 -j RETURN] 
DEBU[2019-03-11T09:56:05.125095277+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -i docker0 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.126053056+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.129446914+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -i docker0 -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.130617732+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.131819595+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -i docker0 ! -o docker0 -j ACCEPT] 
DEBU[2019-03-11T09:56:05.133531836+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:05.134836717+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER] 
DEBU[2019-03-11T09:56:05.135958264+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8] 
DEBU[2019-03-11T09:56:05.136897795+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8] 
DEBU[2019-03-11T09:56:05.137818895+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.138822793+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -o docker0 -j DOCKER] 
DEBU[2019-03-11T09:56:05.144482765+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.145490809+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 
DEBU[2019-03-11T09:56:05.147825467+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.149141820+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.151024113+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -j DOCKER-ISOLATION-STAGE-1] 
DEBU[2019-03-11T09:56:05.152118528+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.153027534+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -I DOCKER-ISOLATION-STAGE-1 -i docker0 ! -o docker0 -j DOCKER-ISOLATION-STAGE-2] 
DEBU[2019-03-11T09:56:05.153891349+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.154736895+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -I DOCKER-ISOLATION-STAGE-2 -o docker0 -j DROP] 
DEBU[2019-03-11T09:56:05.160349501+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -n -L DOCKER-USER] 
DEBU[2019-03-11T09:56:05.161355036+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C DOCKER-USER -j RETURN] 
DEBU[2019-03-11T09:56:05.162196782+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-USER] 
DEBU[2019-03-11T09:56:05.163157424+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -D FORWARD -j DOCKER-USER] 
DEBU[2019-03-11T09:56:05.164843322+01:00] /gnu/store/5g8j76dqjafmah82kd30fc1d1bf74zib-iptables-1.6.2/sbin/iptables, [--wait -I FORWARD -j DOCKER-USER] 
INFO[2019-03-11T09:56:05.185317037+01:00] Loading containers: done.                    
WARN[2019-03-11T09:56:05.185758060+01:00] Could not get operating system name: Error opening /usr/lib/os-release: open /usr/lib/os-release: no such file or directory 
WARN[2019-03-11T09:56:05.204626551+01:00] failed to retrieve /gnu/store/l6nqfq4vyzaxjk8xygm4vr203p04430g-runc-1.0.0-rc6/sbin/runc version: unknown output format: runc version 1.0.0-rc6
spec: 1.0.1-dev
 
WARN[2019-03-11T09:56:05.204981256+01:00] failed to retrieve docker-init version: exec: "docker-init": executable file not found in $PATH 
INFO[2019-03-11T09:56:05.238740939+01:00] Docker daemon                                 commit=v18.09.2 graphdriver(s)=overlay2 version=dev
INFO[2019-03-11T09:56:05.238804379+01:00] Daemon has completed initialization          
DEBU[2019-03-11T09:56:05.239601830+01:00] Registering routers                          
DEBU[2019-03-11T09:56:05.239615931+01:00] Registering GET, /containers/{name:.*}/checkpoints 
DEBU[2019-03-11T09:56:05.239751496+01:00] Registering POST, /containers/{name:.*}/checkpoints 
DEBU[2019-03-11T09:56:05.239837149+01:00] Registering DELETE, /containers/{name}/checkpoints/{checkpoint} 
DEBU[2019-03-11T09:56:05.239916627+01:00] Registering HEAD, /containers/{name:.*}/archive 
DEBU[2019-03-11T09:56:05.239970120+01:00] Registering GET, /containers/json            
DEBU[2019-03-11T09:56:05.240008458+01:00] Registering GET, /containers/{name:.*}/export 
DEBU[2019-03-11T09:56:05.240056898+01:00] Registering GET, /containers/{name:.*}/changes 
DEBU[2019-03-11T09:56:05.240104048+01:00] Registering GET, /containers/{name:.*}/json  
DEBU[2019-03-11T09:56:05.240150451+01:00] Registering GET, /containers/{name:.*}/top   
DEBU[2019-03-11T09:56:05.240198551+01:00] Registering GET, /containers/{name:.*}/logs  
DEBU[2019-03-11T09:56:05.240247455+01:00] Registering GET, /containers/{name:.*}/stats 
DEBU[2019-03-11T09:56:05.240312135+01:00] Registering GET, /containers/{name:.*}/attach/ws 
DEBU[2019-03-11T09:56:05.240360983+01:00] Registering GET, /exec/{id:.*}/json          
DEBU[2019-03-11T09:56:05.240405360+01:00] Registering GET, /containers/{name:.*}/archive 
DEBU[2019-03-11T09:56:05.240453006+01:00] Registering POST, /containers/create         
DEBU[2019-03-11T09:56:05.240491285+01:00] Registering POST, /containers/{name:.*}/kill 
DEBU[2019-03-11T09:56:05.240537431+01:00] Registering POST, /containers/{name:.*}/pause 
DEBU[2019-03-11T09:56:05.240585640+01:00] Registering POST, /containers/{name:.*}/unpause 
DEBU[2019-03-11T09:56:05.240634290+01:00] Registering POST, /containers/{name:.*}/restart 
DEBU[2019-03-11T09:56:05.240709020+01:00] Registering POST, /containers/{name:.*}/start 
DEBU[2019-03-11T09:56:05.240761143+01:00] Registering POST, /containers/{name:.*}/stop 
DEBU[2019-03-11T09:56:05.240808995+01:00] Registering POST, /containers/{name:.*}/wait 
DEBU[2019-03-11T09:56:05.240856588+01:00] Registering POST, /containers/{name:.*}/resize 
DEBU[2019-03-11T09:56:05.240905251+01:00] Registering POST, /containers/{name:.*}/attach 
DEBU[2019-03-11T09:56:05.240952570+01:00] Registering POST, /containers/{name:.*}/copy 
DEBU[2019-03-11T09:56:05.240997749+01:00] Registering POST, /containers/{name:.*}/exec 
DEBU[2019-03-11T09:56:05.241042573+01:00] Registering POST, /exec/{name:.*}/start      
DEBU[2019-03-11T09:56:05.241085715+01:00] Registering POST, /exec/{name:.*}/resize     
DEBU[2019-03-11T09:56:05.241127943+01:00] Registering POST, /containers/{name:.*}/rename 
DEBU[2019-03-11T09:56:05.241176123+01:00] Registering POST, /containers/{name:.*}/update 
DEBU[2019-03-11T09:56:05.241222739+01:00] Registering POST, /containers/prune          
DEBU[2019-03-11T09:56:05.241263538+01:00] Registering POST, /commit                    
DEBU[2019-03-11T09:56:05.241294588+01:00] Registering PUT, /containers/{name:.*}/archive 
DEBU[2019-03-11T09:56:05.241341631+01:00] Registering DELETE, /containers/{name:.*}    
DEBU[2019-03-11T09:56:05.241387679+01:00] Registering GET, /images/json                
DEBU[2019-03-11T09:56:05.241420575+01:00] Registering GET, /images/search              
DEBU[2019-03-11T09:56:05.241453852+01:00] Registering GET, /images/get                 
DEBU[2019-03-11T09:56:05.241484575+01:00] Registering GET, /images/{name:.*}/get       
DEBU[2019-03-11T09:56:05.241529872+01:00] Registering GET, /images/{name:.*}/history   
DEBU[2019-03-11T09:56:05.241573162+01:00] Registering GET, /images/{name:.*}/json      
DEBU[2019-03-11T09:56:05.241618221+01:00] Registering POST, /images/load               
DEBU[2019-03-11T09:56:05.241666228+01:00] Registering POST, /images/create             
DEBU[2019-03-11T09:56:05.241700468+01:00] Registering POST, /images/{name:.*}/push     
DEBU[2019-03-11T09:56:05.241745795+01:00] Registering POST, /images/{name:.*}/tag      
DEBU[2019-03-11T09:56:05.241791610+01:00] Registering POST, /images/prune              
DEBU[2019-03-11T09:56:05.241826390+01:00] Registering DELETE, /images/{name:.*}        
DEBU[2019-03-11T09:56:05.241870105+01:00] Registering OPTIONS, /{anyroute:.*}          
DEBU[2019-03-11T09:56:05.241912413+01:00] Registering GET, /_ping                      
DEBU[2019-03-11T09:56:05.241943268+01:00] Registering GET, /events                     
DEBU[2019-03-11T09:56:05.241971721+01:00] Registering GET, /info                       
DEBU[2019-03-11T09:56:05.242000845+01:00] Registering GET, /version                    
DEBU[2019-03-11T09:56:05.242029998+01:00] Registering GET, /system/df                  
DEBU[2019-03-11T09:56:05.242060342+01:00] Registering POST, /auth                      
DEBU[2019-03-11T09:56:05.242090422+01:00] Registering GET, /volumes                    
DEBU[2019-03-11T09:56:05.242123192+01:00] Registering GET, /volumes/{name:.*}          
DEBU[2019-03-11T09:56:05.242170321+01:00] Registering POST, /volumes/create            
DEBU[2019-03-11T09:56:05.242204144+01:00] Registering POST, /volumes/prune             
DEBU[2019-03-11T09:56:05.242236013+01:00] Registering DELETE, /volumes/{name:.*}       
DEBU[2019-03-11T09:56:05.242280422+01:00] Registering POST, /build                     
DEBU[2019-03-11T09:56:05.242310670+01:00] Registering POST, /build/prune               
DEBU[2019-03-11T09:56:05.242343048+01:00] Registering POST, /build/cancel              
DEBU[2019-03-11T09:56:05.242378602+01:00] Registering POST, /session                   
DEBU[2019-03-11T09:56:05.242407127+01:00] Registering POST, /swarm/init                
DEBU[2019-03-11T09:56:05.242436591+01:00] Registering POST, /swarm/join                
DEBU[2019-03-11T09:56:05.242467910+01:00] Registering POST, /swarm/leave               
DEBU[2019-03-11T09:56:05.242501294+01:00] Registering GET, /swarm                      
DEBU[2019-03-11T09:56:05.242529999+01:00] Registering GET, /swarm/unlockkey            
DEBU[2019-03-11T09:56:05.242564600+01:00] Registering POST, /swarm/update              
DEBU[2019-03-11T09:56:05.242606914+01:00] Registering POST, /swarm/unlock              
DEBU[2019-03-11T09:56:05.242644206+01:00] Registering GET, /services                   
DEBU[2019-03-11T09:56:05.242677944+01:00] Registering GET, /services/{id}              
DEBU[2019-03-11T09:56:05.242720635+01:00] Registering POST, /services/create           
DEBU[2019-03-11T09:56:05.242756024+01:00] Registering POST, /services/{id}/update      
DEBU[2019-03-11T09:56:05.242805262+01:00] Registering DELETE, /services/{id}           
DEBU[2019-03-11T09:56:05.242847943+01:00] Registering GET, /services/{id}/logs         
DEBU[2019-03-11T09:56:05.242895927+01:00] Registering GET, /nodes                      
DEBU[2019-03-11T09:56:05.242927053+01:00] Registering GET, /nodes/{id}                 
DEBU[2019-03-11T09:56:05.242968719+01:00] Registering DELETE, /nodes/{id}              
DEBU[2019-03-11T09:56:05.243009400+01:00] Registering POST, /nodes/{id}/update         
DEBU[2019-03-11T09:56:05.243058816+01:00] Registering GET, /tasks                      
DEBU[2019-03-11T09:56:05.243087847+01:00] Registering GET, /tasks/{id}                 
DEBU[2019-03-11T09:56:05.243128386+01:00] Registering GET, /tasks/{id}/logs            
DEBU[2019-03-11T09:56:05.243173892+01:00] Registering GET, /secrets                    
DEBU[2019-03-11T09:56:05.243205081+01:00] Registering POST, /secrets/create            
DEBU[2019-03-11T09:56:05.243240435+01:00] Registering DELETE, /secrets/{id}            
DEBU[2019-03-11T09:56:05.243284390+01:00] Registering GET, /secrets/{id}               
DEBU[2019-03-11T09:56:05.243327275+01:00] Registering POST, /secrets/{id}/update       
DEBU[2019-03-11T09:56:05.243375740+01:00] Registering GET, /configs                    
DEBU[2019-03-11T09:56:05.243407034+01:00] Registering POST, /configs/create            
DEBU[2019-03-11T09:56:05.243440639+01:00] Registering DELETE, /configs/{id}            
DEBU[2019-03-11T09:56:05.243487942+01:00] Registering GET, /configs/{id}               
DEBU[2019-03-11T09:56:05.243530162+01:00] Registering POST, /configs/{id}/update       
DEBU[2019-03-11T09:56:05.243660746+01:00] Registering GET, /plugins                    
DEBU[2019-03-11T09:56:05.243790291+01:00] Registering GET, /plugins/{name:.*}/json     
DEBU[2019-03-11T09:56:05.243877110+01:00] Registering GET, /plugins/privileges         
DEBU[2019-03-11T09:56:05.243946888+01:00] Registering DELETE, /plugins/{name:.*}       
DEBU[2019-03-11T09:56:05.244027824+01:00] Registering POST, /plugins/{name:.*}/enable  
DEBU[2019-03-11T09:56:05.244107744+01:00] Registering POST, /plugins/{name:.*}/disable 
DEBU[2019-03-11T09:56:05.244186568+01:00] Registering POST, /plugins/pull              
DEBU[2019-03-11T09:56:05.244260064+01:00] Registering POST, /plugins/{name:.*}/push    
DEBU[2019-03-11T09:56:05.244340238+01:00] Registering POST, /plugins/{name:.*}/upgrade 
DEBU[2019-03-11T09:56:05.244420921+01:00] Registering POST, /plugins/{name:.*}/set     
DEBU[2019-03-11T09:56:05.244500333+01:00] Registering POST, /plugins/create            
DEBU[2019-03-11T09:56:05.244583012+01:00] Registering GET, /distribution/{name:.*}/json 
DEBU[2019-03-11T09:56:05.244670955+01:00] Registering GET, /networks                   
DEBU[2019-03-11T09:56:05.253950824+01:00] Registering GET, /networks/                  
DEBU[2019-03-11T09:56:05.254002638+01:00] Registering GET, /networks/{id:.+}           
DEBU[2019-03-11T09:56:05.254058192+01:00] Registering POST, /networks/create           
DEBU[2019-03-11T09:56:05.254093998+01:00] Registering POST, /networks/{id:.*}/connect  
DEBU[2019-03-11T09:56:05.254145047+01:00] Registering POST, /networks/{id:.*}/disconnect 
DEBU[2019-03-11T09:56:05.254194317+01:00] Registering POST, /networks/prune            
DEBU[2019-03-11T09:56:05.254228838+01:00] Registering DELETE, /networks/{id:.*}        
INFO[2019-03-11T09:56:05.254548687+01:00] API listen on /var/run/docker.sock           
^CINFO[2019-03-11T09:56:24.712622167+01:00] Processing signal 'interrupt'                
DEBU[2019-03-11T09:56:24.712740386+01:00] daemon configured with a 15 seconds minimum shutdown timeout 
DEBU[2019-03-11T09:56:24.712773797+01:00] start clean shutdown of all containers with a 15 seconds timeout... 
DEBU[2019-03-11T09:56:24.713084718+01:00] Unix socket /run/docker/libnetwork/74a62366b867f7c576588ffac87c8889da1664e046021b79cea815474a27fe5b.sock doesn't exist. cannot accept client connections 
DEBU[2019-03-11T09:56:24.713135141+01:00] Cleaning up old mountid : start.             
INFO[2019-03-11T09:56:24.713178134+01:00] stopping event stream following graceful shutdown  error="<nil>" module=libcontainerd namespace=moby
DEBU[2019-03-11T09:56:24.713306418+01:00] Cleaning up old mountid : done.              
DEBU[2019-03-11T09:56:24.713393116+01:00] Clean shutdown succeeded                     
allana <at> guixsd ~$ 

-- 
Allan Adair
http://allan.adair.io





Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Tue, 12 Mar 2019 19:48:01 GMT) Full text and rfc822 format available.

Message #56 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Tue, 12 Mar 2019 20:47:04 +0100
[Message part 1 (text/plain, inline)]
Hi Allan,

On Mon, 11 Mar 2019 09:59:19 +0100
Allan Adair <allan <at> adair.io> wrote:

> Sorry for the late response. I was offline for the last week or so.

No problem!

> 
> I ended up having to repeat the first command with sudo
> privileges. Please see below.

Yes, so that looks as if it works fine.  What's the difference to a failed start by herd (log file in /var/log/docker.log) ?
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 18 Mar 2019 10:24:01 GMT) Full text and rfc822 format available.

Message #59 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 18 Mar 2019 11:23:19 +0100
Hi Danny.

Danny Milosavljevic writes:

> Hi Allan,
>
> On Mon, 11 Mar 2019 09:59:19 +0100
> Allan Adair <allan <at> adair.io> wrote:
>
>> Sorry for the late response. I was offline for the last week or so.
>
> No problem!
>
>> 
>> I ended up having to repeat the first command with sudo
>> privileges. Please see below.
>
> Yes, so that looks as if it works fine.  What's the difference to a failed start by herd (log file in /var/log/docker.log) ?

I have never actually been able to start the dockerd service using herd
explicitly. After booting:

allana <at> guixsd ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
allana <at> guixsd ~$ cat /var/log/docker.log
time="2019-03-18T10:23:30.462181353+01:00" level=warning msg="Error while setting daemon root propagation, this is not generally critical but may cause some functionality to not work or fallback to less desirable behavior" dir=/var/lib/docker error="error writing file to signal mount cleanup on shutdown: open /var/run/docker/unmount-on-shutdown: no such file or directory"
time="2019-03-18T10:23:30.465999919+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T10:23:30.466019010+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T10:23:30.466291192+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T10:23:30.466315303+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T10:23:30.466349982+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00012d090, CONNECTING" module=grpc
time="2019-03-18T10:23:30.467362222+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00012d090, READY" module=grpc
time="2019-03-18T10:23:30.467531354+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T10:23:30.467544289+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T10:23:30.467972429+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T10:23:30.467991848+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T10:23:30.468161326+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00012d380, CONNECTING" module=grpc
time="2019-03-18T10:23:30.468444097+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00012d380, READY" module=grpc
time="2019-03-18T10:23:30.471722313+01:00" level=error msg="'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded." storage-driver=overlay2
time="2019-03-18T10:23:30.471762928+01:00" level=error msg="[graphdriver] prior storage driver overlay2 failed: driver not supported"
Error starting daemon: error initializing graphdriver: driver not supported

The service does start after a guix system reconfigure:

allana <at> guixsd ~$ sudo guix system reconfigure /etc/config.scm > /dev/null 2>&1
Password: 
allana <at> guixsd ~$ docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
allana <at> guixsd ~$ cat /var/log/docker.log
time="2019-03-18T11:04:08.548958068+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T11:04:08.549060661+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T11:04:08.549129691+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T11:04:08.549145165+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T11:04:08.549194625+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T11:04:08.549225327+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T11:04:08.549295334+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0007c8730, CONNECTING" module=grpc
time="2019-03-18T11:04:08.549428581+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0007c8730, READY" module=grpc
time="2019-03-18T11:04:08.549823791+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T11:04:08.549852586+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T11:04:08.549895079+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00048c190, CONNECTING" module=grpc
time="2019-03-18T11:04:08.550230781+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00048c190, READY" module=grpc
time="2019-03-18T11:04:08.563100196+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
time="2019-03-18T11:04:08.649791498+01:00" level=info msg="Graph migration to content-addressability took 0.00 seconds"
time="2019-03-18T11:04:08.649963115+01:00" level=warning msg="Your kernel does not support swap memory limit"
time="2019-03-18T11:04:08.650005407+01:00" level=warning msg="Your kernel does not support cgroup rt period"
time="2019-03-18T11:04:08.650018501+01:00" level=warning msg="Your kernel does not support cgroup rt runtime"
time="2019-03-18T11:04:08.650029780+01:00" level=warning msg="Your kernel does not support cgroup blkio weight"
time="2019-03-18T11:04:08.650040103+01:00" level=warning msg="Your kernel does not support cgroup blkio weight_device"
time="2019-03-18T11:04:08.650127344+01:00" level=warning msg="mountpoint for pids not found"
time="2019-03-18T11:04:08.650316692+01:00" level=info msg="Loading containers: start."
time="2019-03-18T11:04:09.231485582+01:00" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2019-03-18T11:04:09.381248432+01:00" level=info msg="Loading containers: done."
time="2019-03-18T11:04:09.381974297+01:00" level=warning msg="Could not get operating system name: Error opening /usr/lib/os-release: open /usr/lib/os-release: no such file or directory"
time="2019-03-18T11:04:09.388621054+01:00" level=warning msg="failed to retrieve /gnu/store/fxmfknby00xva6jlz3m4pjj2jyj2xxiw-runc-1.0.0-rc6/sbin/runc version: unknown output format: runc version 1.0.0-rc6\nspec: 1.0.1-dev\n"
time="2019-03-18T11:04:09.388997410+01:00" level=warning msg="failed to retrieve docker-init version: exec: \"docker-init\": executable file not found in $PATH"
time="2019-03-18T11:04:10.926517059+01:00" level=info msg="Docker daemon" commit=v18.09.3 graphdriver(s)=overlay2 version=dev
time="2019-03-18T11:04:10.926776715+01:00" level=info msg="Daemon has completed initialization"
time="2019-03-18T11:04:10.941524868+01:00" level=info msg="API listen on /var/run/docker.sock"


-- 
Allan Adair
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 18 Mar 2019 10:54:02 GMT) Full text and rfc822 format available.

Message #62 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 18 Mar 2019 11:53:03 +0100
[Message part 1 (text/plain, inline)]
Hi Allan,

thanks for the logs!

I've found the problem now.

daemon/graphdriver/overlay2/overlay.go:

func supportsOverlay() error {
        // We can try to modprobe overlay first before looking at
        // proc/filesystems for when overlay is supported
        exec.Command("modprobe", "overlay").Run()

        f, err := os.Open("/proc/filesystems")
        if err != nil {
                return err
        }
        defer f.Close()

        s := bufio.NewScanner(f)
        for s.Scan() {
                if s.Text() == "nodev\toverlay" {
                        return nil
                }
        }
        logrus.WithField("storage-driver", "overlay2").Error("'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded.")
        return graphdriver.ErrNotSupported
}

We don't load "overlay" explicitly.  The above is some weird contraption--loading kernel modules from random user space programs.  Seriously?

And I suspect that modprobe is not found in your system profile.

As a workaround, try adding "kmod" to the list of packages in your operating-system in your system configuration and reconfigure.

But the real fix is for Docker to stop doing this weird thing in the first place.  Nowadays, modules are autoloaded when someone is accessing the thing (by udev, or just by using it etc).  

In this case, they do

        if err := mount("overlay", mountTarget, "overlay", 0, mountData); err != nil {

later on.  And that's how it should have been detecting it, too.
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 18 Mar 2019 11:06:02 GMT) Full text and rfc822 format available.

Message #65 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 18 Mar 2019 12:05:20 +0100
[Message part 1 (text/plain, inline)]
For our own reference:

# lsmod |grep overlay
# mkdir -p /b
# mount -t overlay none /b
mount: /b: wrong fs type, bad option, bad superblock on /a, missing codepage or helper program, or other error.
# lsmod |grep overlay
overlay               110592  0
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 18 Mar 2019 13:49:02 GMT) Full text and rfc822 format available.

Message #68 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 18 Mar 2019 14:47:48 +0100
Hi Danny. With great excitement I edited my config.scm to include kmod,
ran guix system reconfigure, and rebooted my machine. Unfortunately my
changes did not seem to fix the issue. I hope the session below can help
us further. Thanks so much for working on this issue.

allana <at> guixsd ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
allana <at> guixsd ~$ cat /var/log/docker.log 
time="2019-03-18T14:39:59.788932321+01:00" level=warning msg="Error while setting daemon root propagation, this is not generally critical but may cause some functionality to not work or fallback to less desirable behavior" dir=/var/lib/docker error="error writing file to signal mount cleanup on shutdown: open /var/run/docker/unmount-on-shutdown: no such file or directory"
time="2019-03-18T14:39:59.797964377+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:39:59.797982675+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:39:59.798127164+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:39:59.798220831+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:39:59.798291248+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000771980, CONNECTING" module=grpc
time="2019-03-18T14:39:59.800603937+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000771980, READY" module=grpc
time="2019-03-18T14:39:59.801234292+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:39:59.801254794+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:39:59.801329244+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:39:59.801366954+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:39:59.801507445+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000d79d0, CONNECTING" module=grpc
time="2019-03-18T14:39:59.802331100+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000d79d0, READY" module=grpc
time="2019-03-18T14:39:59.815614194+01:00" level=error msg="'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded." storage-driver=overlay2
time="2019-03-18T14:39:59.815664314+01:00" level=error msg="[graphdriver] prior storage driver overlay2 failed: driver not supported"
Error starting daemon: error initializing graphdriver: driver not supported
allana <at> guixsd ~$ cat /etc/config.scm
(use-modules (gnu)
             (gnu system nss)
	     (gnu services))
(use-service-modules desktop docker)
(use-package-modules certs gnome linux)

(operating-system
 (host-name "guixsd")
 (timezone "Europe/Oslo")
 (locale "en_US.utf8")

  (bootloader (bootloader-configuration
               (bootloader grub-bootloader)
               (target "/dev/sda")))

  (file-systems (cons (file-system
		       (device (file-system-label "my-root"))
		       (mount-point "/")
		       (type "ext4"))
                      %base-file-systems))

  (users (cons (user-account
                (name "allana")
                (group "users")
                (supplementary-groups '("wheel"
					"docker"
					"netdev"
                                        "audio"
					"video"))
                (home-directory "/home/allana"))
               %base-user-accounts))

  ;; This is where we specify system-wide packages.
  (packages (cons* nss-certs         ;for HTTPS access
                   gvfs              ;for user mounts
		   kmod              ;for modprobe/dockerd
                   %base-packages))

  (services (cons* (console-keymap-service "no-latin1")
                   (gnome-desktop-service)
		   (service docker-service-type)
                   %desktop-services))

  ;; Allow resolution of '.local' host names with mDNS.
  (name-service-switch %mdns-host-lookup-nss))
allana <at> guixsd ~$ sudo herd start dockerd
Password: 
Service dockerd could not be started.
herd: failed to start service dockerd
allana <at> guixsd ~$ sudo guix system reconfigure /etc/config.scm > /dev/null 2>&1
allana <at> guixsd ~$ docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
allana <at> guixsd ~$ cat /var/log/docker.log 
time="2019-03-18T14:43:00.850449641+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:43:00.850524161+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:43:00.850623186+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:43:00.850638306+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:43:00.850682621+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:43:00.850705685+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:43:00.850749857+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000496e0, CONNECTING" module=grpc
time="2019-03-18T14:43:00.850880352+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000496e0, READY" module=grpc
time="2019-03-18T14:43:00.851069787+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:43:00.851088244+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:43:00.851153314+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000499d0, CONNECTING" module=grpc
time="2019-03-18T14:43:00.851266607+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000499d0, READY" module=grpc
time="2019-03-18T14:43:00.874110624+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
time="2019-03-18T14:43:01.002014039+01:00" level=info msg="Graph migration to content-addressability took 0.00 seconds"
time="2019-03-18T14:43:01.002217610+01:00" level=warning msg="Your kernel does not support swap memory limit"
time="2019-03-18T14:43:01.002293632+01:00" level=warning msg="Your kernel does not support cgroup rt period"
time="2019-03-18T14:43:01.002307271+01:00" level=warning msg="Your kernel does not support cgroup rt runtime"
time="2019-03-18T14:43:01.002318768+01:00" level=warning msg="Your kernel does not support cgroup blkio weight"
time="2019-03-18T14:43:01.002328780+01:00" level=warning msg="Your kernel does not support cgroup blkio weight_device"
time="2019-03-18T14:43:01.002447782+01:00" level=warning msg="mountpoint for pids not found"
time="2019-03-18T14:43:01.002919567+01:00" level=info msg="Loading containers: start."
time="2019-03-18T14:43:01.596297744+01:00" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2019-03-18T14:43:01.664423600+01:00" level=info msg="Loading containers: done."
time="2019-03-18T14:43:01.672193823+01:00" level=warning msg="Could not get operating system name: Error opening /usr/lib/os-release: open /usr/lib/os-release: no such file or directory"
time="2019-03-18T14:43:01.735588173+01:00" level=warning msg="failed to retrieve /gnu/store/fxmfknby00xva6jlz3m4pjj2jyj2xxiw-runc-1.0.0-rc6/sbin/runc version: unknown output format: runc version 1.0.0-rc6\nspec: 1.0.1-dev\n"
time="2019-03-18T14:43:01.747943901+01:00" level=warning msg="failed to retrieve docker-init version: exec: \"docker-init\": executable file not found in $PATH"
time="2019-03-18T14:43:01.901777278+01:00" level=info msg="Docker daemon" commit=v18.09.3 graphdriver(s)=overlay2 version=dev
time="2019-03-18T14:43:01.911529576+01:00" level=info msg="Daemon has completed initialization"
time="2019-03-18T14:43:01.918913081+01:00" level=info msg="API listen on /var/run/docker.sock"


Danny Milosavljevic writes:

> Hi Allan,
>
> thanks for the logs!
>
> I've found the problem now.
>
> daemon/graphdriver/overlay2/overlay.go:
>
> func supportsOverlay() error {
>         // We can try to modprobe overlay first before looking at
>         // proc/filesystems for when overlay is supported
>         exec.Command("modprobe", "overlay").Run()
>
>         f, err := os.Open("/proc/filesystems")
>         if err != nil {
>                 return err
>         }
>         defer f.Close()
>
>         s := bufio.NewScanner(f)
>         for s.Scan() {
>                 if s.Text() == "nodev\toverlay" {
>                         return nil
>                 }
>         }
>         logrus.WithField("storage-driver", "overlay2").Error("'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded.")
>         return graphdriver.ErrNotSupported
> }
>
> We don't load "overlay" explicitly.  The above is some weird contraption--loading kernel modules from random user space programs.  Seriously?
>
> And I suspect that modprobe is not found in your system profile.
>
> As a workaround, try adding "kmod" to the list of packages in your operating-system in your system configuration and reconfigure.
>
> But the real fix is for Docker to stop doing this weird thing in the first place.  Nowadays, modules are autoloaded when someone is accessing the thing (by udev, or just by using it etc).  
>
> In this case, they do
>
>         if err := mount("overlay", mountTarget, "overlay", 0, mountData); err != nil {
>
> later on.  And that's how it should have been detecting it, too.


-- 
Allan Adair
http://allan.adair.io




Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Mon, 25 Mar 2019 21:47:02 GMT) Full text and rfc822 format available.

Message #71 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: Allan Adair <allan <at> adair.io>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Mon, 25 Mar 2019 22:46:51 +0100
[Message part 1 (text/plain, inline)]
Hi Allan,

I've pushed a new way to get rid of this bug to guix master.

Could you try

  guix pull

and then

  guix reconfigure

and report back?
[Message part 2 (application/pgp-signature, inline)]

Information forwarded to bug-guix <at> gnu.org:
bug#34333; Package guix. (Tue, 26 Mar 2019 14:16:02 GMT) Full text and rfc822 format available.

Message #74 received at 34333 <at> debbugs.gnu.org (full text, mbox):

From: Allan Adair <allan <at> adair.io>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Björn Höfling <bjoern.hoefling <at> bjoernhoefling.de>,
 34333 <at> debbugs.gnu.org, Allan Adair <allan <at> adair.io>
Subject: Re: bug#34333: Docker daemon failing to start on boot
Date: Tue, 26 Mar 2019 15:15:03 +0100
Danny Milosavljevic writes:

> Hi Allan,
>
> I've pushed a new way to get rid of this bug to guix master.
>
> Could you try
>
>   guix pull
>
> and then
>
>   guix reconfigure
>
> and report back?

Success! Thank you very much.

-- 
Allan Adair
http://allan.adair.io




bug closed, send any further explanations to 34333 <at> debbugs.gnu.org and allan <at> adair.io Request was from Danny Milosavljevic <dannym <at> scratchpost.org> to control <at> debbugs.gnu.org. (Tue, 26 Mar 2019 14:18:01 GMT) Full text and rfc822 format available.

bug archived. Request was from Debbugs Internal Request <help-debbugs <at> gnu.org> to internal_control <at> debbugs.gnu.org. (Wed, 24 Apr 2019 11:24:05 GMT) Full text and rfc822 format available.

This bug report was last modified 4 years and 341 days ago.

Previous Next


GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.