search

QubesOS / qubes-issues

The Qubes OS Project issue tracker
https://www.qubes-os.org/doc/issue-tracking/
532 stars 46 forks source link

/usr/local fails to persist in Qubes-Whonix 14 / mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe #4095

Closed adrelanos closed 6 years ago

adrelanos commented 6 years ago

Qubes OS version:

R4

Affected component(s):

Qubes-Whonix

Steps to reproduce the behavior:

Install https://github.com/QubesOS/updates-status/issues/581 Boot Create file within /usr/local. Reboot

Expected behavior:

File persisting in /usr/local.

Actual behavior:

File not persisting in /usr/local.

General notes:

This is a blocker for the release of Qubes-Whonix 14 since we are writing Tor config into /usr/local/etc/torrc.d.

(Tor comes disabled by default, gets enabled during boot run by the user. So Tor config would be lost on every reboot.)

Related issues:

adrelanos commented 6 years ago 
-- Logs begin at Tue 2018-07-17 08:43:36 UTC, end at Tue 2018-07-17 08:45:06 UTC. --
Jul 17 08:43:36 host kernel: Linux version 4.14.41-1.pvops.qubes.x86_64 (user@build-fedora4) (gcc version 6.4.1 20170727 (Red Hat 6.4.1-1) (GCC)) #1 SMP Wed May 16 21:43:05 UTC 2018
Jul 17 08:43:36 host kernel: Command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 nopat
Jul 17 08:43:36 host kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
Jul 17 08:43:36 host kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
Jul 17 08:43:36 host kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
Jul 17 08:43:36 host kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
Jul 17 08:43:36 host kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
Jul 17 08:43:36 host kernel: e820: BIOS-provided physical RAM map:
Jul 17 08:43:36 host kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
Jul 17 08:43:36 host kernel: BIOS-e820: [mem 0x00000000000a0000-0x00000000000fefff] reserved
Jul 17 08:43:36 host kernel: BIOS-e820: [mem 0x00000000000ff000-0x00000000000fffff] ACPI data
Jul 17 08:43:36 host kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000fa0003ff] usable
Jul 17 08:43:36 host kernel: BIOS-e820: [mem 0x00000000fc000000-0x00000000fc007fff] ACPI data
Jul 17 08:43:36 host kernel: x86/PAT: PAT support disabled.
Jul 17 08:43:36 host kernel: NX (Execute Disable) protection: active
Jul 17 08:43:36 host kernel: DMI not present or invalid.
Jul 17 08:43:36 host kernel: Hypervisor detected: Xen HVM
Jul 17 08:43:36 host kernel: Xen version 4.8.
Jul 17 08:43:36 host kernel: Xen Platform PCI: unrecognised magic value
Jul 17 08:43:36 host kernel: HVMOP_pagetable_dying not supported
Jul 17 08:43:36 host kernel: tsc: Fast TSC calibration failed
Jul 17 08:43:36 host kernel: tsc: Unable to calibrate against PIT
Jul 17 08:43:36 host kernel: tsc: No reference (HPET/PMTIMER) available
Jul 17 08:43:36 host kernel: e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
Jul 17 08:43:36 host kernel: e820: remove [mem 0x000a0000-0x000fffff] usable
Jul 17 08:43:36 host kernel: e820: last_pfn = 0xfa000 max_arch_pfn = 0x400000000
Jul 17 08:43:36 host kernel: MTRR default type: uncachable
Jul 17 08:43:36 host kernel: MTRR fixed ranges disabled:
Jul 17 08:43:36 host kernel:   00000-FFFFF uncachable
Jul 17 08:43:36 host kernel: MTRR variable ranges disabled:
Jul 17 08:43:36 host kernel:   0 disabled
Jul 17 08:43:36 host kernel:   1 disabled
Jul 17 08:43:36 host kernel:   2 disabled
Jul 17 08:43:36 host kernel:   3 disabled
Jul 17 08:43:36 host kernel:   4 disabled
Jul 17 08:43:36 host kernel:   5 disabled
Jul 17 08:43:36 host kernel:   6 disabled
Jul 17 08:43:36 host kernel:   7 disabled
Jul 17 08:43:36 host kernel: MTRR: Disabled
Jul 17 08:43:36 host kernel: CPU MTRRs all blank - virtualized system.
Jul 17 08:43:36 host kernel: x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC  
Jul 17 08:43:36 host kernel: Base memory trampoline at [ffff880000099000] 99000 size 24576
Jul 17 08:43:36 host kernel: BRK [0x02a78000, 0x02a78fff] PGTABLE
Jul 17 08:43:36 host kernel: BRK [0x02a79000, 0x02a79fff] PGTABLE
Jul 17 08:43:36 host kernel: BRK [0x02a7a000, 0x02a7afff] PGTABLE
Jul 17 08:43:36 host kernel: BRK [0x02a7b000, 0x02a7bfff] PGTABLE
Jul 17 08:43:36 host kernel: RAMDISK: [mem 0x02aa5000-0x039e7fff]
Jul 17 08:43:36 host kernel: ACPI: Early table checksum verification disabled
Jul 17 08:43:36 host kernel: ACPI: RSDP 0x00000000000FFFC0 000024 (v02 Xen   )
Jul 17 08:43:36 host kernel: ACPI: XSDT 0x00000000FC007F70 000034 (v01 Xen    HVM      00000000 HVML 00000000)
Jul 17 08:43:36 host kernel: ACPI: FACP 0x00000000FC007D70 00010C (v05 Xen    HVM      00000000 HVML 00000000)
Jul 17 08:43:36 host kernel: ACPI: DSDT 0x00000000FC001050 006C9B (v05 Xen    HVM      00000000 INTL 20160831)
Jul 17 08:43:36 host kernel: ACPI: FACS 0x00000000FC001010 000040
Jul 17 08:43:36 host kernel: ACPI: FACS 0x00000000FC001010 000040
Jul 17 08:43:36 host kernel: ACPI: APIC 0x00000000FC007E80 00003C (v02 Xen    HVM      00000000 HVML 00000000)
Jul 17 08:43:36 host kernel: ACPI: Local APIC address 0xfee00000
Jul 17 08:43:36 host kernel: No NUMA configuration found
Jul 17 08:43:36 host kernel: Faking a node at [mem 0x0000000000000000-0x00000000f9ffffff]
Jul 17 08:43:36 host kernel: NODE_DATA(0) allocated [mem 0xf9fd3000-0xf9ffdfff]
Jul 17 08:43:36 host kernel: Zone ranges:
Jul 17 08:43:36 host kernel:   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
Jul 17 08:43:36 host kernel:   DMA32    [mem 0x0000000001000000-0x00000000f9ffffff]
Jul 17 08:43:36 host kernel:   Normal   empty
Jul 17 08:43:36 host kernel:   Device   empty
Jul 17 08:43:36 host kernel: Movable zone start for each node
Jul 17 08:43:36 host kernel: Early memory node ranges
Jul 17 08:43:36 host kernel:   node   0: [mem 0x0000000000001000-0x000000000009ffff]
Jul 17 08:43:36 host kernel:   node   0: [mem 0x0000000000100000-0x00000000f9ffffff]
Jul 17 08:43:36 host kernel: Initmem setup node 0 [mem 0x0000000000001000-0x00000000f9ffffff]
Jul 17 08:43:36 host kernel: On node 0 totalpages: 1023903
Jul 17 08:43:36 host kernel:   DMA zone: 64 pages used for memmap
Jul 17 08:43:36 host kernel:   DMA zone: 22 pages reserved
Jul 17 08:43:36 host kernel:   DMA zone: 3999 pages, LIFO batch:0
Jul 17 08:43:36 host kernel:   DMA32 zone: 15936 pages used for memmap
Jul 17 08:43:36 host kernel:   DMA32 zone: 1019904 pages, LIFO batch:31
Jul 17 08:43:36 host kernel: ACPI: Local APIC address 0xfee00000
Jul 17 08:43:36 host kernel: ACPI: No IOAPIC entries present
Jul 17 08:43:36 host kernel: Using ACPI for processor (LAPIC) configuration information
Jul 17 08:43:36 host kernel: smpboot: Allowing 2 CPUs, 0 hotplug CPUs
Jul 17 08:43:36 host kernel: e820: [mem 0xfc008000-0xffffffff] available for PCI devices
Jul 17 08:43:36 host kernel: Booting paravirtualized kernel on Xen PVH
Jul 17 08:43:36 host kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
Jul 17 08:43:36 host kernel: random: get_random_bytes called from start_kernel+0xc3/0x6bf with crng_init=0
Jul 17 08:43:36 host kernel: setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:2 nr_node_ids:1
Jul 17 08:43:36 host kernel: percpu: Embedded 44 pages/cpu @ffff8800f9c00000 s139864 r8192 d32168 u1048576
Jul 17 08:43:36 host kernel: pcpu-alloc: s139864 r8192 d32168 u1048576 alloc=1*2097152
Jul 17 08:43:36 host kernel: pcpu-alloc: [0] 0 1 
Jul 17 08:43:36 host kernel: xen: PV spinlocks enabled
Jul 17 08:43:36 host kernel: PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
Jul 17 08:43:36 host kernel: Built 1 zonelists, mobility grouping on.  Total pages: 1007881
Jul 17 08:43:36 host kernel: Policy zone: DMA32
Jul 17 08:43:36 host kernel: Kernel command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 nopat
Jul 17 08:43:36 host kernel: PID hash table entries: 4096 (order: 3, 32768 bytes)
Jul 17 08:43:36 host kernel: Memory: 3986584K/4095612K available (12300K kernel code, 1394K rwdata, 3760K rodata, 2536K init, 1280K bss, 109028K reserved, 0K cma-reserved)
Jul 17 08:43:36 host kernel: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
Jul 17 08:43:36 host kernel: Kernel/User page tables isolation: enabled
Jul 17 08:43:36 host kernel: ftrace: allocating 35252 entries in 138 pages
Jul 17 08:43:36 host kernel: Hierarchical RCU implementation.
Jul 17 08:43:36 host kernel:         RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=2.
Jul 17 08:43:36 host kernel:         Tasks RCU enabled.
Jul 17 08:43:36 host kernel: RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
Jul 17 08:43:36 host kernel: Using NULL legacy PIC
Jul 17 08:43:36 host kernel: NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 0
Jul 17 08:43:36 host kernel: xen:events: Using FIFO-based ABI
Jul 17 08:43:36 host kernel: xen:events: Xen HVM callback vector for event delivery is enabled
Jul 17 08:43:36 host kernel:         Offload RCU callbacks from CPUs: .
Jul 17 08:43:36 host kernel: Console: colour dummy device 80x25
Jul 17 08:43:36 host kernel: console [hvc0] enabled
Jul 17 08:43:36 host kernel: tsc: Unable to calibrate against PIT
Jul 17 08:43:36 host kernel: tsc: No reference (HPET/PMTIMER) available
Jul 17 08:43:36 host kernel: tsc: Detected 2793.660 MHz processor
Jul 17 08:43:36 host kernel: Calibrating delay loop (skipped), value calculated using timer frequency.. 5587.32 BogoMIPS (lpj=2793660)
Jul 17 08:43:36 host kernel: pid_max: default: 32768 minimum: 301
Jul 17 08:43:36 host kernel: ACPI: Core revision 20170728
Jul 17 08:43:36 host kernel: ACPI: 1 ACPI AML tables successfully acquired and loaded
Jul 17 08:43:36 host kernel: ACPI: setting ELCR to 0200 (from ffff)
Jul 17 08:43:36 host kernel: Security Framework initialized
Jul 17 08:43:36 host kernel: Yama: becoming mindful.
Jul 17 08:43:36 host kernel: AppArmor: AppArmor disabled by boot time parameter
Jul 17 08:43:36 host kernel: Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
Jul 17 08:43:36 host kernel: Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
Jul 17 08:43:36 host kernel: Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
Jul 17 08:43:36 host kernel: Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
Jul 17 08:43:36 host kernel: CPU: Physical Processor ID: 0
Jul 17 08:43:36 host kernel: CPU: Processor Core ID: 0
Jul 17 08:43:36 host kernel: mce: CPU supports 2 MCE banks
Jul 17 08:43:36 host kernel: Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
Jul 17 08:43:36 host kernel: Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
Jul 17 08:43:36 host kernel: Spectre V2 : Mitigation: Full generic retpoline
Jul 17 08:43:36 host kernel: Spectre V2 : Spectre v2 mitigation: Enabling Indirect Branch Prediction Barrier
Jul 17 08:43:36 host kernel: Spectre V2 : Enabling Restricted Speculation for firmware calls
Jul 17 08:43:36 host kernel: Freeing SMP alternatives memory: 28K
Jul 17 08:43:36 host kernel: smpboot: Max logical packages: 1
Jul 17 08:43:36 host kernel: x2apic: IRQ remapping doesn't support X2APIC mode
Jul 17 08:43:36 host kernel: clocksource: xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
Jul 17 08:43:36 host kernel: Xen: using vcpuop timer interface
Jul 17 08:43:36 host kernel: installing Xen timer for CPU 0
Jul 17 08:43:36 host kernel: smpboot: CPU0: Intel(R) Core(TM) i7-3840QM CPU @ 2.80GHz (family: 0x6, model: 0x3a, stepping: 0x9)
Jul 17 08:43:36 host kernel: cpu 0 spinlock event irq 5
Jul 17 08:43:36 host kernel: Performance Events: unsupported p6 CPU model 58 no PMU driver, software events only.
Jul 17 08:43:36 host kernel: Hierarchical SRCU implementation.
Jul 17 08:43:36 host kernel: NMI watchdog: Perf event create on CPU 0 failed with -2
Jul 17 08:43:36 host kernel: NMI watchdog: Perf NMI watchdog permanently disabled
Jul 17 08:43:36 host kernel: smp: Bringing up secondary CPUs ...
Jul 17 08:43:36 host kernel: installing Xen timer for CPU 1
Jul 17 08:43:36 host kernel: x86: Booting SMP configuration:
Jul 17 08:43:36 host kernel: .... node  #0, CPUs:      #1
Jul 17 08:43:36 host kernel: cpu 1 spinlock event irq 11
Jul 17 08:43:36 host kernel: smp: Brought up 1 node, 2 CPUs
Jul 17 08:43:36 host kernel: smpboot: Total of 2 processors activated (11174.64 BogoMIPS)
Jul 17 08:43:36 host kernel: devtmpfs: initialized
Jul 17 08:43:36 host kernel: x86/mm: Memory block size: 128MB
Jul 17 08:43:36 host kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
Jul 17 08:43:36 host kernel: futex hash table entries: 512 (order: 3, 32768 bytes)
Jul 17 08:43:36 host kernel: pinctrl core: initialized pinctrl subsystem
Jul 17 08:43:36 host kernel: RTC time: 165:165:165, date: 165/165/65
Jul 17 08:43:36 host kernel: NET: Registered protocol family 16
Jul 17 08:43:36 host kernel: xen:grant_table: Grant tables using version 1 layout
Jul 17 08:43:36 host kernel: Grant table initialized
Jul 17 08:43:36 host kernel: cpuidle: using governor menu
Jul 17 08:43:36 host kernel: ACPI: bus type PCI registered
Jul 17 08:43:36 host kernel: PCI: Fatal: No config space access function found
Jul 17 08:43:36 host kernel: HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
Jul 17 08:43:36 host kernel: ACPI: Added _OSI(Module Device)
Jul 17 08:43:36 host kernel: ACPI: Added _OSI(Processor Device)
Jul 17 08:43:36 host kernel: ACPI: Added _OSI(3.0 _SCP Extensions)
Jul 17 08:43:36 host kernel: ACPI: Added _OSI(Processor Aggregator Device)
Jul 17 08:43:36 host kernel: ACPI: SCI (ACPI GSI 9) not registered
Jul 17 08:43:36 host kernel: ACPI: Interpreter enabled
Jul 17 08:43:36 host kernel: ACPI: (supports S0)
Jul 17 08:43:36 host kernel: ACPI: Using platform specific model for interrupt routing
Jul 17 08:43:36 host kernel: PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
Jul 17 08:43:36 host kernel: ACPI: GPE 0x02 active on init
Jul 17 08:43:36 host kernel: ACPI: Enabled 1 GPEs in block 00 to 0F
Jul 17 08:43:36 host kernel: acpi LNXCPU:02: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:03: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:04: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:05: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:06: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:07: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:08: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:09: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0a: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0b: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0c: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0d: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0e: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:0f: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:10: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:11: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:12: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:13: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:14: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:15: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:16: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:17: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:18: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1a: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1b: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1c: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1d: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1e: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:1f: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:20: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:22: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:23: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:24: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:25: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:26: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:27: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:28: Still not present
Jul 17 08:43:36 host kernel: acpi LNXCPU:29: Still not present
Jul 17 08:43:36 host kernel: xen:balloon: Initialising balloon driver
Jul 17 08:43:36 host kernel: random: fast init done
Jul 17 08:43:36 host kernel: vgaarb: loaded
Jul 17 08:43:36 host kernel: SCSI subsystem initialized
Jul 17 08:43:36 host kernel: libata version 3.00 loaded.
Jul 17 08:43:36 host kernel: ACPI: bus type USB registered
Jul 17 08:43:36 host kernel: usbcore: registered new interface driver usbfs
Jul 17 08:43:36 host kernel: usbcore: registered new interface driver hub
Jul 17 08:43:36 host kernel: usbcore: registered new device driver usb
Jul 17 08:43:36 host kernel: EDAC MC: Ver: 3.0.0
Jul 17 08:43:36 host kernel: dmi: Firmware registration failed.
Jul 17 08:43:36 host kernel: PCI: Using ACPI for IRQ routing
Jul 17 08:43:36 host kernel: PCI: System does not support PCI
Jul 17 08:43:36 host kernel: NetLabel: Initializing
Jul 17 08:43:36 host kernel: NetLabel:  domain hash size = 128
Jul 17 08:43:36 host kernel: NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
Jul 17 08:43:36 host kernel: NetLabel:  unlabeled traffic allowed by default
Jul 17 08:43:36 host kernel: clocksource: Switched to clocksource xen
Jul 17 08:43:36 host kernel: VFS: Disk quotas dquot_6.6.0
Jul 17 08:43:36 host kernel: VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
Jul 17 08:43:36 host kernel: pnp: PnP ACPI init
Jul 17 08:43:36 host kernel: pnp: PnP ACPI: found 0 devices
Jul 17 08:43:36 host kernel: NET: Registered protocol family 2
Jul 17 08:43:36 host kernel: TCP established hash table entries: 32768 (order: 6, 262144 bytes)
Jul 17 08:43:36 host kernel: TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
Jul 17 08:43:36 host kernel: TCP: Hash tables configured (established 32768 bind 32768)
Jul 17 08:43:36 host kernel: UDP hash table entries: 2048 (order: 4, 65536 bytes)
Jul 17 08:43:36 host kernel: UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
Jul 17 08:43:36 host kernel: NET: Registered protocol family 1
Jul 17 08:43:36 host kernel: PCI: CLS 0 bytes, default 64
Jul 17 08:43:36 host kernel: Unpacking initramfs...
Jul 17 08:43:36 host kernel: Freeing initrd memory: 15628K
Jul 17 08:43:36 host kernel: audit: initializing netlink subsys (disabled)
Jul 17 08:43:36 host kernel: Initialise system trusted keyrings
Jul 17 08:43:36 host kernel: Key type blacklist registered
Jul 17 08:43:36 host kernel: audit: type=2000 audit(1531817012.528:1): state=initialized audit_enabled=0 res=1
Jul 17 08:43:36 host kernel: workingset: timestamp_bits=36 max_order=20 bucket_order=0
Jul 17 08:43:36 host kernel: zbud: loaded
Jul 17 08:43:36 host kernel: NET: Registered protocol family 38
Jul 17 08:43:36 host kernel: Key type asymmetric registered
Jul 17 08:43:36 host kernel: Asymmetric key parser 'x509' registered
Jul 17 08:43:36 host kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
Jul 17 08:43:36 host kernel: io scheduler noop registered
Jul 17 08:43:36 host kernel: io scheduler deadline registered
Jul 17 08:43:36 host kernel: io scheduler cfq registered (default)
Jul 17 08:43:36 host kernel: io scheduler mq-deadline registered
Jul 17 08:43:36 host kernel: atomic64_test: passed for x86-64 platform with CX8 and with SSE
Jul 17 08:43:36 host kernel: intel_idle: does not run on family 6 model 58
Jul 17 08:43:36 host kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
Jul 17 08:43:36 host kernel: Non-volatile memory driver v1.3
Jul 17 08:43:36 host kernel: Linux agpgart interface v0.103
Jul 17 08:43:36 host kernel: libphy: Fixed MDIO Bus: probed
Jul 17 08:43:36 host kernel: usbcore: registered new interface driver usbserial
Jul 17 08:43:36 host kernel: usbcore: registered new interface driver usbserial_generic
Jul 17 08:43:36 host kernel: usbserial: USB Serial support registered for generic
Jul 17 08:43:36 host kernel: i8042: PNP: No PS/2 controller found.
Jul 17 08:43:36 host kernel: mousedev: PS/2 mouse device common for all mice
Jul 17 08:43:36 host kernel: device-mapper: uevent: version 1.0.3
Jul 17 08:43:36 host kernel: device-mapper: ioctl: 4.37.0-ioctl (2017-09-20) initialised: dm-devel@redhat.com
Jul 17 08:43:36 host kernel: dmi-sysfs: dmi entry is absent.
Jul 17 08:43:36 host kernel: hidraw: raw HID events driver (C) Jiri Kosina
Jul 17 08:43:36 host kernel: usbcore: registered new interface driver usbhid
Jul 17 08:43:36 host kernel: usbhid: USB HID core driver
Jul 17 08:43:36 host kernel: drop_monitor: Initializing network drop monitor service
Jul 17 08:43:36 host kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
Jul 17 08:43:36 host kernel: Initializing XFRM netlink socket
Jul 17 08:43:36 host kernel: NET: Registered protocol family 10
Jul 17 08:43:36 host kernel: Segment Routing with IPv6
Jul 17 08:43:36 host kernel: mip6: Mobile IPv6
Jul 17 08:43:36 host kernel: NET: Registered protocol family 17
Jul 17 08:43:36 host kernel: RAS: Correctable Errors collector initialized.
Jul 17 08:43:36 host kernel: AVX version of gcm_enc/dec engaged.
Jul 17 08:43:36 host kernel: AES CTR mode by8 optimization enabled
Jul 17 08:43:36 host kernel: sched_clock: Marking stable (562005283, 0)->(57398166629504, -57397604624221)
Jul 17 08:43:36 host kernel: registered taskstats version 1
Jul 17 08:43:36 host kernel: Loading compiled-in X.509 certificates
Jul 17 08:43:36 host kernel: zswap: loaded using pool lzo/zbud
Jul 17 08:43:36 host kernel: Key type big_key registered
Jul 17 08:43:36 host kernel: Key type encrypted registered
Jul 17 08:43:36 host kernel: xenbus_probe_frontend: Device with no driver: device/vbd/51712
Jul 17 08:43:36 host kernel: xenbus_probe_frontend: Device with no driver: device/vbd/51728
Jul 17 08:43:36 host kernel: xenbus_probe_frontend: Device with no driver: device/vbd/51744
Jul 17 08:43:36 host kernel: xenbus_probe_frontend: Device with no driver: device/vbd/51760
Jul 17 08:43:36 host kernel: xenbus_probe_frontend: Device with no driver: device/vif/0
Jul 17 08:43:36 host kernel:   Magic number: 1:252:3141
Jul 17 08:43:36 host kernel: hctosys: unable to open rtc device (rtc0)
Jul 17 08:43:36 host kernel: Freeing unused kernel memory: 2536K
Jul 17 08:43:36 host kernel: Write protecting the kernel read-only data: 18432k
Jul 17 08:43:36 host kernel: Freeing unused kernel memory: 2024K
Jul 17 08:43:36 host kernel: Freeing unused kernel memory: 336K
Jul 17 08:43:36 host kernel: rodata_test: all tests were successful
Jul 17 08:43:36 host kernel: Invalid max_queues (4), will use default max: 2.
Jul 17 08:43:36 host kernel: blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Jul 17 08:43:36 host kernel: blkfront: xvdb: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Jul 17 08:43:36 host kernel: blkfront: xvdc: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Jul 17 08:43:36 host kernel: blkfront: xvdd: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Jul 17 08:43:36 host kernel: clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2844dbaa7c5, max_idle_ns: 440795307629 ns
Jul 17 08:43:36 host kernel: random: sfdisk: uninitialized urandom read (4 bytes read)
Jul 17 08:43:36 host kernel:  xvdc: xvdc1
Jul 17 08:43:36 host kernel: random: mkswap: uninitialized urandom read (16 bytes read)
Jul 17 08:43:36 host kernel: EXT4-fs (xvda): mounted filesystem with ordered data mode. Opts: (null)
Jul 17 08:43:36 host kernel: EXT4-fs (xvdd): mounting ext3 file system using the ext4 subsystem
Jul 17 08:43:36 host kernel: EXT4-fs (xvdd): mounted filesystem with ordered data mode. Opts: (null)
Jul 17 08:43:36 host kernel: random: systemd: uninitialized urandom read (16 bytes read)
Jul 17 08:43:36 host kernel: random: systemd: uninitialized urandom read (16 bytes read)
Jul 17 08:43:36 host kernel: random: systemd: uninitialized urandom read (16 bytes read)
Jul 17 08:43:36 host systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
Jul 17 08:43:36 host systemd[1]: Detected virtualization xen.
Jul 17 08:43:36 host systemd[1]: Detected architecture x86-64.
Jul 17 08:43:36 host systemd[1]: Set hostname to <host>.
Jul 17 08:43:36 host systemd[1]: Listening on Journal Audit Socket.
Jul 17 08:43:36 host systemd[1]: Listening on Journal Socket (/dev/log).
Jul 17 08:43:36 host systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Jul 17 08:43:36 host systemd[1]: Listening on Journal Socket.
Jul 17 08:43:36 host systemd[1]: Listening on Syslog Socket.
Jul 17 08:43:36 host systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
Jul 17 08:43:36 host systemd-journald[196]: Journal started
Jul 17 08:43:36 host systemd-journald[196]: Runtime journal (/run/log/journal/d3202370ccfd4a5b87f33e36df2baf12) is 1.9M, max 15.6M, 13.6M free.
Jul 17 08:43:36 host systemd-fsck[194]: /dev/xvda: clean, 92981/655360 files, 737716/2621440 blocks
Jul 17 08:43:36 host systemd-modules-load[195]: Inserted module 'xen_evtchn'
Jul 17 08:43:36 host kernel: xen:xen_evtchn: Event-channel device installed
Jul 17 08:43:36 host systemd[1]: Started File System Check on Root Device.
Jul 17 08:43:36 host systemd-modules-load[195]: Inserted module 'xen_blkback'
Jul 17 08:43:36 host systemd-modules-load[195]: Inserted module 'xen_gntalloc'
Jul 17 08:43:36 host kernel: u2mfn: loading out-of-tree module taints kernel.
Jul 17 08:43:36 host systemd[1]: Starting Remount Root and Kernel File Systems...
Jul 17 08:43:36 host systemd-modules-load[195]: Inserted module 'xen_gntdev'
Jul 17 08:43:36 host systemd-modules-load[195]: Inserted module 'u2mfn'
Jul 17 08:43:36 host systemd[1]: Mounted /proc/xen.
Jul 17 08:43:36 host systemd[1]: Started Load Kernel Modules.
Jul 17 08:43:36 host systemd[1]: Starting Qubes DB agent...
Jul 17 08:43:36 host systemd[1]: Starting Apply Kernel Variables...
Jul 17 08:43:36 host systemd[1]: Mounting Configuration File System...
Jul 17 08:43:36 host systemd[1]: Mounted Configuration File System.
Jul 17 08:43:36 host kernel: EXT4-fs (xvda): re-mounted. Opts: discard
Jul 17 08:43:36 host systemd[1]: Started Remount Root and Kernel File Systems.
Jul 17 08:43:36 host systemd[1]: Started Create Static Device Nodes in /dev.
Jul 17 08:43:36 host systemd[1]: Started Apply Kernel Variables.
Jul 17 08:43:36 host systemd[1]: Starting udev Kernel Device Manager...
Jul 17 08:43:36 host kernel: random: crng init done
Jul 17 08:43:36 host kernel: random: 5 urandom warning(s) missed due to ratelimiting
Jul 17 08:43:36 host systemd[1]: Starting udev Coldplug all Devices...
Jul 17 08:43:36 host systemd[1]: Starting Flush Journal to Persistent Storage...
Jul 17 08:43:36 host systemd[1]: Reached target Local File Systems (Pre).
Jul 17 08:43:36 host systemd-journald[196]: Runtime journal (/run/log/journal/d3202370ccfd4a5b87f33e36df2baf12) is 1.9M, max 15.6M, 13.6M free.
Jul 17 08:43:36 host systemd[1]: Started Flush Journal to Persistent Storage.
Jul 17 08:43:36 host systemd[1]: Started Qubes DB agent.
Jul 17 08:43:36 host systemd[1]: Starting Init Qubes Services settings...
Jul 17 08:43:36 host systemd[1]: Starting Load/Save Random Seed...
Jul 17 08:43:36 host systemd[1]: Started udev Coldplug all Devices.
Jul 17 08:43:36 host systemd[1]: Started Load/Save Random Seed.
Jul 17 08:43:36 host systemd[1]: Started udev Kernel Device Manager.
Jul 17 08:43:36 host systemd[1]: Started Init Qubes Services settings.
Jul 17 08:43:36 host systemd[1]: Starting Initialize and mount /rw and /home...
Jul 17 08:43:36 host systemd[1]: Starting Init Qubes+Whonix services and settings...
Jul 17 08:43:36 host systemd[1]: Starting Adjust root filesystem size...
Jul 17 08:43:36 host systemd[1]: Started Init Qubes+Whonix services and settings.
Jul 17 08:43:36 host mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device management: checking /dev/xvdb
Jul 17 08:43:36 host resize-rootfs-if-needed.sh[297]: root filesystem already at the right size
Jul 17 08:43:36 host systemd[1]: Started Adjust root filesystem size.
Jul 17 08:43:36 host kernel: RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 163840 ms ovfl timer
Jul 17 08:43:36 host kernel: RAPL PMU: hw unit of domain pp0-core 2^-16 Joules
Jul 17 08:43:36 host kernel: RAPL PMU: hw unit of domain package 2^-16 Joules
Jul 17 08:43:36 host kernel: RAPL PMU: hw unit of domain pp1-gpu 2^-16 Joules
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device management: fsck.ext4 of /dev/xvdb succeeded
Jul 17 08:43:36 host kernel: input: PC Speaker as /devices/platform/pcspkr/input/input0
Jul 17 08:43:36 host kernel: Error: Driver 'pcspkr' is already registered, aborting...
Jul 17 08:43:36 host kernel: EXT4-fs (xvdb): mounted filesystem with ordered data mode. Opts: discard
Jul 17 08:43:36 host mount-dirs.sh[295]: Checking /rw
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device size management: enlarging /dev/xvdb
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device size management: resize2fs of /dev/xvdb succeeded
Jul 17 08:43:36 host mount-dirs.sh[295]: Finished checking /rw
Jul 17 08:43:36 host kernel: intel_rapl: Found RAPL domain package
Jul 17 08:43:36 host kernel: intel_rapl: Found RAPL domain core
Jul 17 08:43:36 host kernel: intel_rapl: RAPL package 0 domain package locked by BIOS
Jul 17 08:43:36 host kernel: xen_netfront: Initialising Xen virtual ethernet driver
Jul 17 08:43:36 host mount-dirs.sh[295]: Mounting /rw/home onto /home
Jul 17 08:43:37 host systemd[1]: Found device /dev/hvc0.
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/spool/cron onto /var/spool/cron
Jul 17 08:43:37 host systemd[1]: Found device /dev/xvdc1.
Jul 17 08:43:37 host systemd[1]: Activating swap /dev/xvdc1...
Jul 17 08:43:37 host kernel: Adding 1048572k swap on /dev/xvdc1.  Priority:-2 extents:1 across:1048572k SSFS
Jul 17 08:43:37 host systemd[1]: Activated swap /dev/xvdc1.
Jul 17 08:43:37 host systemd[1]: Reached target Swap.
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/tor onto /var/lib/tor
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonix onto /var/lib/whonix
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonixcheck onto /var/lib/whonixcheck
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/whonix-setup-wizard onto /var/cache/whonix-setup-wizard
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/anon-base-files onto /var/cache/anon-base-files
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/tb-updater onto /var/cache/tb-updater
Jul 17 08:43:37 host systemd[1]: Started Initialize and mount /rw and /home.
Jul 17 08:43:37 host systemd[1]: Reached target Local File Systems.
Jul 17 08:43:37 host systemd[1]: Starting Create Volatile Files and Directories...
Jul 17 08:43:37 host systemd[1]: Starting Whonix firewall loader...
Jul 17 08:43:37 host systemd[1]: Starting Early Qubes VM settings...
Jul 17 08:43:37 host systemd-tmpfiles[374]: [/usr/lib/tmpfiles.d/openvpn.conf:1] Duplicate line for path "/run/openvpn", ignoring.
Jul 17 08:43:37 host systemd[1]: Started Early Qubes VM settings.
Jul 17 08:43:37 host systemd[1]: Started Create Volatile Files and Directories.
Jul 17 08:43:37 host systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jul 17 08:43:37 host systemd[1]: Started Entropy daemon using the HAVEGE algorithm.
Jul 17 08:43:37 host enable-firewall[375]: OK: Loading Whonix firewall...
Jul 17 08:43:37 host systemd[1]: Started Update UTMP about System Boot/Shutdown.
Jul 17 08:43:37 host systemd[1]: Reached target System Initialization.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9153.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9150 to Whonix-Gateway port 9151.
Jul 17 08:43:37 host systemd[1]: Started Daily Cleanup of Temporary Directories.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9150.sock to Whonix-Gateway port 9150.
Jul 17 08:43:37 host systemd[1]: Listening on D-Bus System Message Bus Socket.
Jul 17 08:43:37 host enable-firewall[375]: OK: Skipping firewall mode detection since already set to 'full'.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9153 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9050 to Whonix-Gateway port 9050.
Jul 17 08:43:37 host systemd[1]: Started Periodically check for updates.
Jul 17 08:43:37 host systemd[1]: Started Update system time each 6h.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/tor/control to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: apt-daily.timer: Adding 3h 22min 40.776093s random time.
Jul 17 08:43:37 host systemd[1]: Started Daily apt download activities.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9050.sock to Whonix-Gateway port 9050.
Jul 17 08:43:37 host enable-firewall[375]: OK: (Full torified network access allowed.)
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9152 to Whonix-Gateway port 9152.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:11109 to Whonix-Gateway port 9119.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9051 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: apt-daily-upgrade.timer: Adding 4min 57.479956s random time.
Jul 17 08:43:37 host systemd[1]: Started Daily apt upgrade and clean activities.
Jul 17 08:43:37 host systemd[1]: Reached target Timers.
Jul 17 08:43:37 host systemd[1]: Starting redirect 127.0.0.1:9151 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9051.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/tor/socks to Whonix-Gateway port 9050.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9152.sock to Whonix-Gateway port 9152.
Jul 17 08:43:37 host systemd[1]: Starting redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9151.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9153.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9150 to Whonix-Gateway port 9151.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9150.sock to Whonix-Gateway port 9150.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9153 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9050 to Whonix-Gateway port 9050.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/tor/control to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9050.sock to Whonix-Gateway port 9050.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9152 to Whonix-Gateway port 9152.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:11109 to Whonix-Gateway port 9119.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9051 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect 127.0.0.1:9151 to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9051.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/tor/socks to Whonix-Gateway port 9050.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9152.sock to Whonix-Gateway port 9152.
Jul 17 08:43:37 host systemd[1]: Listening on redirect /var/run/anon-ws-disable-stacked-tor/127.0.0.1_9151.sock to Whonix-Gateway port 9051.
Jul 17 08:43:37 host systemd[1]: Reached target Sockets.
Jul 17 08:43:37 host systemd[1]: Reached target Basic System.
Jul 17 08:43:37 host systemd[1]: Starting LSB: VirtualBox Linux Additions...
Jul 17 08:43:37 host systemd[1]: Starting System Logging Service...
Jul 17 08:43:37 host systemd[1]: Starting Time Sanity Check...
Jul 17 08:43:37 host systemd[1]: Starting Qubes-Whonix post init...
Jul 17 08:43:37 host systemd[1]: Starting LSB: Set sysfs variables from /etc/sysfs.conf...
Jul 17 08:43:37 host systemd[1]: Starting Login Service...
Jul 17 08:43:37 host systemd[1]: Starting Xen driver domain device daemon...
Jul 17 08:43:37 host systemd[1]: Starting msgcollector...
Jul 17 08:43:37 host systemd[1]: Starting Qubes memory information reporter...
Jul 17 08:43:37 host qubes-whonix-postinit[448]: ++ qubesdb-read /qubes-vm-type
Jul 17 08:43:37 host systemd[1]: Starting /home/user from /etc/skel Population at First Boot Service...
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + qubes_vm_type=AppVM
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + '[' AppVM = TemplateVM ']'
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + /usr/lib/qubes-whonix/bind-directories
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + '[' -e /usr/lib/qubes/bind-dirs.sh ']'
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + exit 0
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + /usr/lib/qubes-whonix/replace-ips
Jul 17 08:43:37 host systemd[1]: Started D-Bus System Message Bus.
Jul 17 08:43:37 host first-boot-skel[462]: + set -e
Jul 17 08:43:37 host first-boot-skel[462]: + command -v qubesdb-read
Jul 17 08:43:37 host first-boot-skel[462]: ++ qubesdb-read /qubes-vm-type
Jul 17 08:43:37 host first-boot-skel[462]: + qubes_vm_type=AppVM
Jul 17 08:43:37 host first-boot-skel[462]: + cache_folder=/var/cache/anon-base-files
Jul 17 08:43:37 host first-boot-skel[462]: + '[' AppVM = TemplateVM ']'
Jul 17 08:43:37 host first-boot-skel[462]: + done_file=/var/cache/anon-base-files/first-boot-skel.done
Jul 17 08:43:37 host first-boot-skel[462]: + '[' -e /var/cache/anon-base-files/first-boot-skel.done ']'
Jul 17 08:43:37 host first-boot-skel[462]: + exit 0
Jul 17 08:43:37 host start[447]: The clock is sane.
Jul 17 08:43:37 host start[447]: Current time Tue Jul 17 08:43:37 UTC 2018 (1531817017).
Jul 17 08:43:37 host xl[455]: Failed to read config file: /etc/xen/xl.conf: No such file or directory
Jul 17 08:43:37 host kernel: nf_conntrack version 0.5.0 (2560 buckets, 10240 max)
Jul 17 08:43:37 host liblogging-stdlog[443]:  [origin software="rsyslogd" swVersion="8.24.0" x-pid="443" x-info="http://www.rsyslog.com"] start
Jul 17 08:43:37 host systemd[1]: Started System Logging Service.
Jul 17 08:43:37 host systemd[1]: Started Time Sanity Check.
Jul 17 08:43:37 host systemd[1]: Started Xen driver domain device daemon.
Jul 17 08:43:37 host systemd[1]: Started msgcollector.
Jul 17 08:43:37 host systemd[1]: Started Qubes memory information reporter.
Jul 17 08:43:37 host systemd[1]: Started /home/user from /etc/skel Population at First Boot Service.
Jul 17 08:43:37 host systemd[1]: Started LSB: VirtualBox Linux Additions.
Jul 17 08:43:37 host sysfsutils[450]: Setting sysfs variables....
Jul 17 08:43:37 host systemd[1]: Started LSB: Set sysfs variables from /etc/sysfs.conf.
Jul 17 08:43:37 host systemd[1]: Started Login Service.
Jul 17 08:43:37 host systemd-logind[452]: New seat seat0.
Jul 17 08:43:37 host systemd[1]: Starting Qubes remote exec agent...
Jul 17 08:43:37 host systemd[1]: Starting Boot Clock Randomization...
Jul 17 08:43:37 host systemd[1]: Started Qubes remote exec agent.
Jul 17 08:43:37 host qrexec-agent[528]: executed user:QUBESRPC qubes.WaitForSession dom0 pid 537
Jul 17 08:43:37 host qrexec-agent[537]: pam_unix(qrexec:session): session opened for user user by (uid=0)
Jul 17 08:43:37 host qubes-whonix-postinit[448]: + '[' -e /usr/share/anon-gw-base-files/gateway ']'
Jul 17 08:43:37 host systemd[1]: Started Qubes-Whonix post init.
Jul 17 08:43:37 host systemd[1]: Starting Whonix legacy versions fixes...
Jul 17 08:43:37 host systemd[1]: Starting Copy Tor Browser from /var/cache/tb-binary to user home at First Boot Service...
Jul 17 08:43:37 host first-boot-home-population[568]: + user_name=user
Jul 17 08:43:37 host first-boot-home-population[568]: + home_dir=/home/user
Jul 17 08:43:37 host first-boot-home-population[568]: + cache_folder=/home/user/.tb
Jul 17 08:43:37 host first-boot-home-population[568]: + done_file=/home/user/.tb/first-boot-home-population.done
Jul 17 08:43:37 host first-boot-home-population[568]: + '[' -e /home/user/.tb/first-boot-home-population.done ']'
Jul 17 08:43:37 host first-boot-home-population[568]: + exit 0
Jul 17 08:43:37 host systemd[1]: Started Copy Tor Browser from /var/cache/tb-binary to user home at First Boot Service.
Jul 17 08:43:37 host enable-firewall[375]: OK: Qubes DNS firewall rules ok.
Jul 17 08:43:37 host kernel: ip6_tables: (C) 2000-2006 Netfilter Core Team
Jul 17 08:43:37 host systemd[1]: Started Whonix legacy versions fixes.
Jul 17 08:43:37 host haveged[388]: haveged: ver: 1.9.1; arch: x86; vend: GenuineIntel; build: (gcc 6.3.0 ITV); collect: 128K
Jul 17 08:43:37 host haveged[388]: haveged: cpu: (L4 VC); data: 32K (L4 V); inst: 32K (L4 V); idx: 22/40; sz: 31886/59215
Jul 17 08:43:37 host haveged[388]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B):  last entropy estimate 8.00181
Jul 17 08:43:37 host haveged[388]: haveged: fills: 0, generated: 0
Jul 17 08:43:37 host start[518]: + 51 955380289
Jul 17 08:44:28 host systemd[1]: Time has been changed
Jul 17 08:44:28 host systemd[1]: apt-daily-upgrade.timer: Adding 24min 49.330945s random time.
Jul 17 08:44:28 host systemd[1]: apt-daily.timer: Adding 9h 15min 10.286463s random time.
Jul 17 08:44:28 host start[518]: Changed time from Tue Jul 17 08:43:37 UTC 2018 (1531817017.515824445)
Jul 17 08:44:28 host enable-firewall[375]: OK: The firewall should not show any messages,
Jul 17 08:44:28 host enable-firewall[375]: OK: besides output beginning with prefix OK:...
Jul 17 08:44:28 host enable-firewall[375]: OK: Whonix firewall loaded.
Jul 17 08:44:28 host systemd[1]: Started Whonix firewall loader.
Jul 17 08:44:28 host systemd[1]: Started Whonix firewall watcher.
Jul 17 08:44:28 host systemd[1]: Starting Qubes GUI Agent...
Jul 17 08:44:28 host firewall-restarter[636]: + set -e
Jul 17 08:44:28 host firewall-restarter[636]: + mkdir --parents /var/run/qubes-service
Jul 17 08:44:28 host firewall-restarter[636]: + mkdir --parents /var/run/sdwdate
Jul 17 08:44:28 host systemd[1]: Reached target Network (Pre).
Jul 17 08:44:28 host start[518]:                to Tue Jul 17 08:44:28 UTC 2018 (1531817068.959044045).
Jul 17 08:44:28 host systemd[1]: Starting sets up Qubes-Whonix-Gateway external and internal network interface...
Jul 17 08:44:28 host network-proxy-setup[639]: + source /usr/lib/qubes-whonix/utility_functions.sh
Jul 17 08:44:28 host systemd[1]: Started Qubes GUI Agent.
Jul 17 08:44:28 host systemd[1]: Started Boot Clock Randomization.
Jul 17 08:44:28 host network-proxy-setup[639]: ++ systemctl -q is-active qubes-updates-proxy-forwarder.socket
Jul 17 08:44:28 host systemd[1]: Starting Anonymizing overlay network for TCP (multi-instance-master)...
Jul 17 08:44:28 host firewall-restarter[636]: + chown --recursive sdwdate:sdwdate /var/run/sdwdate
Jul 17 08:44:28 host firewall-restarter[636]: ++ mktemp
Jul 17 08:44:28 host firewall-restarter[636]: + inotifywait_subshell_fifo=/tmp/tmp.v8HZKhwCC3
Jul 17 08:44:28 host firewall-restarter[636]: + rm --force /tmp/tmp.v8HZKhwCC3
Jul 17 08:44:28 host firewall-restarter[636]: + mkfifo /tmp/tmp.v8HZKhwCC3
Jul 17 08:44:28 host firewall-restarter[636]: + inotifywait_subshell_pid=658
Jul 17 08:44:28 host systemd[1]: Started Anonymizing overlay network for TCP (multi-instance-master).
Jul 17 08:44:28 host network-proxy-setup[639]: ++ PROXY_SERVER=http://10.137.255.254:8082/
Jul 17 08:44:28 host network-proxy-setup[639]: ++ PROXY_META='<meta name="application-name" content="tor proxy"/>'
Jul 17 08:44:28 host network-proxy-setup[639]: ++ qubesdb-read /qubes-vm-type
Jul 17 08:44:28 host firewall-restarter[636]: + '[' -f /var/run/sdwdate/first_success ']'
Jul 17 08:44:28 host firewall-restarter[636]: + '[' -f /var/run/qubes-service/whonix-secure-proxy ']'
Jul 17 08:44:28 host firewall-restarter[636]: + read file_name
Jul 17 08:44:28 host firewall-restarter[636]: + wait 662
Jul 17 08:44:28 host network-proxy-setup[639]: + qubes_vm_type=AppVM
Jul 17 08:44:28 host network-proxy-setup[639]: + '[' AppVM = TemplateVM ']'
Jul 17 08:44:28 host network-proxy-setup[639]: + INTERFACE=eth1
Jul 17 08:44:28 host network-proxy-setup[639]: + '[' '!' -e /usr/share/anon-gw-base-files/gateway ']'
Jul 17 08:44:28 host network-proxy-setup[639]: + exit 0
Jul 17 08:44:28 host systemd[1]: Started sets up Qubes-Whonix-Gateway external and internal network interface.
Jul 17 08:44:28 host systemd[1]: Starting Qubes misc post-boot actions...
Jul 17 08:44:28 host systemd[1]: Reached target Network.
Jul 17 08:44:28 host firewall-restarter[636]: + inotifywait --quiet --recursive --monitor --event create --format %w%f /var/run/sdwdate/ /var/run/qubes-service/
Jul 17 08:44:28 host systemd[1]: Starting Permit User Sessions...
Jul 17 08:44:28 host systemd[1]: Reached target Network is Online.
Jul 17 08:44:28 host systemd[1]: Starting Qubes Whonix Torified Updates Proxy Check...
Jul 17 08:44:29 host torified-updates-proxy-check[666]: ++ qubesdb-read /qubes-vm-type
Jul 17 08:44:29 host torified-updates-proxy-check[666]: + qubes_vm_type=AppVM
Jul 17 08:44:29 host torified-updates-proxy-check[666]: + '[' '!' AppVM = TemplateVM ']'
Jul 17 08:44:29 host torified-updates-proxy-check[666]: + exit 0
Jul 17 08:44:29 host systemd[1]: Starting LSB: Anonymous remailer client and server...
Jul 17 08:44:29 host systemd[1]: Starting OpenVPN service...
Jul 17 08:44:29 host systemd[1]: Starting anon-ws-disable-stacked-tor...
Jul 17 08:44:29 host systemd[1]: Starting /etc/rc.local Compatibility...
Jul 17 08:44:29 host systemd[1]: Started anon-ws-disable-stacked-tor.
Jul 17 08:44:29 host systemd[1]: Starting Secure Distributed Web Date...
Jul 17 08:44:29 host systemd[1]: Started whonixcheck.
Jul 17 08:44:29 host qrexec-agent[528]: executed user:QUBESRPC qubes.SetMonitorLayout dom0 pid 691
Jul 17 08:44:29 host systemd[1]: Started Permit User Sessions.
Jul 17 08:44:29 host qrexec-agent[691]: pam_unix(qrexec:session): session opened for user user by (uid=0)
Jul 17 08:44:29 host systemd[1]: Started Qubes Whonix Torified Updates Proxy Check.
Jul 17 08:44:29 host systemd[1]: Started OpenVPN service.
Jul 17 08:44:29 host systemd[1]: Started /etc/rc.local Compatibility.
Jul 17 08:44:29 host qubes-gui[646]: Waiting on /var/run/xf86-qubes-socket socket...
Jul 17 08:44:29 host misc-post.sh[664]: Failed to read /qubes-gateway6
Jul 17 08:44:29 host sudo[693]:     user : TTY=unknown ; PWD=/ ; USER=whonixcheck ; COMMAND=/usr/lib/whonixcheck/whonixcheck --autostart --gui --cli
Jul 17 08:44:29 host sudo[693]: pam_unix(sudo:session): session opened for user whonixcheck by (uid=0)
Jul 17 08:44:29 host su[696]: Successful su for user by root
Jul 17 08:44:29 host su[696]: + ??? root:user
Jul 17 08:44:29 host su[696]: pam_unix(su:session): session opened for user user by (uid=0)
Jul 17 08:44:29 host systemd[1]: Created slice User Slice of user.
Jul 17 08:44:29 host systemd[1]: Started Session c2 of user user.
Jul 17 08:44:29 host systemd[1]: Started Getty on tty1.
Jul 17 08:44:29 host systemd[1]: Started Session c1 of user user.
Jul 17 08:44:29 host misc-post.sh[664]: Cannot get device udp-fragmentation-offload settings: Operation not supported
Jul 17 08:44:29 host systemd[1]: Started Serial Getty on hvc0.
Jul 17 08:44:29 host systemd[1]: Reached target Login Prompts.
Jul 17 08:44:29 host mixmaster[669]: Not starting Mixmaster Daemon: remailer mode not enabled in /etc/mixmaster/remailer.conf.
Jul 17 08:44:29 host systemd[1]: Starting User Manager for UID 1000...
Jul 17 08:44:29 host mixmaster[669]: Not starting Mixmaster Daemon: remailer mode not enabled in /etc/mixmaster/remailer.conf..
Jul 17 08:44:29 host misc-post.sh[664]: Cannot get device udp-fragmentation-offload settings: Operation not supported
Jul 17 08:44:29 host systemd[726]: pam_unix(systemd-user:session): session opened for user user by (uid=0)
Jul 17 08:44:29 host systemd[1]: Started anon-ws-disable-stacked-tor.
Jul 17 08:44:29 host systemd[1]: Started LSB: Anonymous remailer client and server.
Jul 17 08:44:29 host misc-post.sh[664]: Cannot get device udp-fragmentation-offload settings: Operation not supported
Jul 17 08:44:29 host misc-post.sh[664]: Cannot get device udp-fragmentation-offload settings: Operation not supported
Jul 17 08:44:29 host misc-post.sh[664]: Could not change any device features
Jul 17 08:44:29 host systemd-logind[452]: New session c3 of user user.
Jul 17 08:44:29 host systemd[1]: Started Session c3 of user user.
Jul 17 08:44:29 host misc-post.sh[664]: SIOCADDRT: File exists
Jul 17 08:44:29 host misc-post.sh[664]: SIOCADDRT: File exists
Jul 17 08:44:29 host systemd[1]: Started Qubes misc post-boot actions.
Jul 17 08:44:29 host socat-unix-sockets[733]: INFO: No processes launched into background, ok.
Jul 17 08:44:29 host systemd[726]: Reached target Paths.
Jul 17 08:44:29 host systemd[726]: Reached target Timers.
Jul 17 08:44:29 host systemd[726]: Listening on GnuPG cryptographic agent (access for web browsers).
Jul 17 08:44:29 host systemd[726]: Listening on GnuPG cryptographic agent and passphrase cache.
Jul 17 08:44:29 host systemd[726]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jul 17 08:44:29 host systemd[726]: Listening on GnuPG network certificate management daemon.
Jul 17 08:44:29 host systemd[726]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jul 17 08:44:29 host systemd[726]: Reached target Sockets.
Jul 17 08:44:29 host systemd[726]: Reached target Basic System.
Jul 17 08:44:29 host systemd[726]: Reached target Default.
Jul 17 08:44:29 host systemd[726]: Startup finished in 63ms.
Jul 17 08:44:29 host systemd[1]: Started User Manager for UID 1000.
Jul 17 08:44:29 host systemd[1]: Started Secure Distributed Web Date.
Jul 17 08:44:29 host systemd[1]: Reached target Multi-User System.
Jul 17 08:44:29 host systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jul 17 08:44:29 host sdwdate[681]: 2018-07-17 08:44:29 - sdwdate - INFO - sdwdate started. PID: 681
Jul 17 08:44:29 host sdwdate[681]: 2018-07-17 08:44:29 - sdwdate - INFO - create temp_dir: /tmp/tmp.wyUmPQtbqs
Jul 17 08:44:29 host systemd[1]: Started Update UTMP about System Runlevel Changes.
Jul 17 08:44:29 host qubes-gui[646]: Ok, somebody connected.
Jul 17 08:44:29 host sdwdate[681]: 2018-07-17 08:44:29 - sdwdate - INFO - Tor socks host: 10.137.0.11 Tor socks port: 9108
Jul 17 08:44:29 host sdwdate[681]: 2018-07-17 08:44:29 - sdwdate - INFO - Running sdwdate main loop. iteration: 1 / 10000
Jul 17 08:44:29 host qrexec-agent[691]: pam_unix(qrexec:session): session closed for user user
Jul 17 08:44:29 host qrexec-agent[528]: send exit code 0
Jul 17 08:44:29 host qrexec-agent[528]: pid 691 exited with 0
Jul 17 08:44:29 host qrexec-agent[528]: eintr
Jul 17 08:44:30 host systemd[1]: Startup finished in 3.932s (kernel) + 2.342s (userspace) = 6.275s.
Jul 17 08:44:30 host systemd[1]: Started redirect /var/run/tor/control to Whonix-Gateway port 9051.
Jul 17 08:44:30 host gnome-keyring-daemon[949]: couldn't access control socket: /run/user/1000/keyring/control: No such file or directory
Jul 17 08:44:30 host qrexec-agent[537]: pam_unix(qrexec:session): session closed for user user
Jul 17 08:44:30 host qrexec-agent[528]: send exit code 0
Jul 17 08:44:30 host qrexec-agent[528]: pid 537 exited with 0
Jul 17 08:44:30 host qrexec-agent[528]: eintr
Jul 17 08:44:30 host su[989]: Successful su for user by root
Jul 17 08:44:30 host su[989]: + ??? root:user
Jul 17 08:44:30 host su[989]: pam_unix(su:session): session opened for user user by (uid=0)
Jul 17 08:44:30 host systemd[1]: Started Session c4 of user user.
Jul 17 08:44:30 host systemd-logind[452]: New session c4 of user user.
Jul 17 08:44:30 host su[989]: pam_unix(su:session): session closed for user user
Jul 17 08:44:30 host qrexec-agent[528]: eintr
Jul 17 08:44:30 host pulseaudio[985]: vchan module loading
Jul 17 08:44:30 host systemd-logind[452]: Removed session c4.
Jul 17 08:44:30 host pulseaudio[985]: play libvchan_fd_for_select=19, ctrl=0x60521a39b360
Jul 17 08:44:30 host pulseaudio[985]: rec libvchan_fd_for_select=23, ctrl=0x60521a39b470
Jul 17 08:44:30 host pulseaudio[985]: sink cork req state =1, now state=-2
Jul 17 08:44:30 host pulseaudio[985]: source cork req state =1, now state=-2
Jul 17 08:44:31 host sdwdate[681]: 2018-07-17 08:44:31 - sdwdate - INFO - The clock is sane.
Jul 17 08:44:31 host sdwdate[681]: Within build timestamp Fri Jul 13 15:36:35 UTC 2018 and expiration timestamp Tue May 17 10:00:00 UTC 2033.
Jul 17 08:44:31 host sdwdate[681]: Clock within consensus parameters consensus/valid-after 2018-07-17 08:00:00 and consensus/valid-until 2018-07-17 11:00:00.
Jul 17 08:44:31 host sdwdate[681]: 2018-07-17 08:44:31 - sdwdate - WARNING - Tor is not yet fully bootstrapped. Tor circuit: not established.
Jul 17 08:44:31 host firewall-restarter[636]: + '[' /var/run/sdwdate/msg = /var/run/sdwdate/first_success ']'
Jul 17 08:44:31 host firewall-restarter[636]: + '[' /var/run/sdwdate/msg = /var/run/qubes-service/whonix-secure-proxy ']'
Jul 17 08:44:31 host firewall-restarter[636]: + read file_name
Jul 17 08:44:32 host sudo[693]: pam_unix(sudo:session): session closed for user whonixcheck
Jul 17 08:44:35 host pulseaudio[985]: source cork req state =2, now state=1
Jul 17 08:44:35 host pulseaudio[985]: sink cork req state =2, now state=1
Jul 17 08:44:36 host systemd[1]: Started Update time from ClockVM.
Jul 17 08:44:36 host qvm-sync-clock[1822]: Request refused
Jul 17 08:44:36 host systemd[1]: qubes-sync-time.service: Main process exited, code=exited, status=126/n/a
Jul 17 08:44:36 host systemd[1]: qubes-sync-time.service: Unit entered failed state.
Jul 17 08:44:36 host systemd[1]: qubes-sync-time.service: Failed with result 'exit-code'.
Jul 17 08:45:06 host sudo[1989]:     user : TTY=pts/0 ; PWD=/home/user ; USER=root ; COMMAND=/bin/journalctl
Jul 17 08:45:06 host sudo[1989]: pam_unix(sudo:session): session opened for user root by user(uid=0)
adrelanos commented 6 years ago

Found one interesting error message.

Jul 17 08:43:36 host mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe

Any idea?

sudo systemctl status qubes-mount-dirs
-- Logs begin at Tue 2018-07-17 08:43:36 UTC, end at Tue 2018-07-17 08:51:11 UTC. --
Jul 17 08:43:36 host systemd[1]: Starting Initialize and mount /rw and /home...
Jul 17 08:43:36 host mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device management: checking /dev/xvdb
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device management: fsck.ext4 of /dev/xvdb succeeded
Jul 17 08:43:36 host mount-dirs.sh[295]: Checking /rw
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device size management: enlarging /dev/xvdb
Jul 17 08:43:36 host mount-dirs.sh[295]: Private device size management: resize2fs of /dev/xvdb succeeded
Jul 17 08:43:36 host mount-dirs.sh[295]: Finished checking /rw
Jul 17 08:43:36 host mount-dirs.sh[295]: Mounting /rw/home onto /home
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/spool/cron onto /var/spool/cron
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/tor onto /var/lib/tor
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonix onto /var/lib/whonix
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonixcheck onto /var/lib/whonixcheck
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/whonix-setup-wizard onto /var/cache/whonix-setup-wizard
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/anon-base-files onto /var/cache/anon-base-files
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/tb-updater onto /var/cache/tb-updater
Jul 17 08:43:37 host systemd[1]: Started Initialize and mount /rw and /home.
● qubes-mount-dirs.service - Initialize and mount /rw and /home
   Loaded: loaded (/lib/systemd/system/qubes-mount-dirs.service; enabled; vendor preset: enabled)
   Active: active (exited) since Tue 2018-07-17 08:43:37 UTC; 7min ago
  Process: 295 ExecStart=/usr/lib/qubes/init/mount-dirs.sh (code=exited, status=0/SUCCESS)
 Main PID: 295 (code=exited, status=0/SUCCESS)
    Tasks: 0 (limit: 4915)
   CGroup: /system.slice/qubes-mount-dirs.service
sudo journalctl -u qubes-mount-dirs
Jul 17 08:43:36 host mount-dirs.sh[295]: Finished checking /rw
Jul 17 08:43:36 host mount-dirs.sh[295]: Mounting /rw/home onto /home
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/spool/cron onto /var/spool/cron
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/tor onto /var/lib/tor
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonix onto /var/lib/whonix
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/lib/whonixcheck onto /var/lib/whonixcheck
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/whonix-setup-wizard onto /var/cache/whonix-setup-wizard
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/anon-base-files onto /var/cache/anon-base-files
Jul 17 08:43:37 host mount-dirs.sh[295]: Bind mounting /rw/bind-dirs/var/cache/tb-updater onto /var/cache/tb-updater
Jul 17 08:43:37 host systemd[1]: Started Initialize and mount /rw and /home.
sudo mount
/dev/xvda on / type ext4 (rw,noatime,discard,data=ordered)
/dev/xvdd on /lib/modules/4.14.41-1.pvops.qubes.x86_64 type ext3 (ro,relatime,data=ordered)
sysfs on /sys type sysfs (rw,relatime)
proc on /proc type proc (rw,relatime)
devtmpfs on /dev type devtmpfs (rw,nosuid,size=1993304k,nr_inodes=498326,mode=755)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,size=1048576k,nr_inodes=40076)
devpts on /dev/pts type devpts (rw,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,nodev,size=160304k,nr_inodes=40076,mode=755)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k,nr_inodes=40076)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,size=160304k,nr_inodes=40076,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/pids type cgroup (rw,nosuid,nodev,noexec,relatime,pids)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=34,pgrp=1,timeout=0,minproto=5,maxproto=5,direct)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
mqueue on /dev/mqueue type mqueue (rw,relatime)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime,pagesize=2M)
xen on /proc/xen type xenfs (rw,relatime)
configfs on /sys/kernel/config type configfs (rw,relatime)
/dev/xvdb on /rw type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /home type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/spool/cron type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/tor type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/whonix type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/whonixcheck type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/cache/whonix-setup-wizard type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/cache/anon-base-files type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/cache/tb-updater type ext4 (rw,relatime,discard,data=ordered)
none on /run/msgcollector type tmpfs (rw,relatime,size=10240k,nr_inodes=40076)
tmpfs on /run/user/1000 type tmpfs (rw,nosuid,nodev,relatime,size=32060k,nr_inodes=40076,mode=700,uid=1000,gid=1000)
adrelanos commented 6 years ago

Enabled xtrace for /usr/lib/qubes/init/mount-dirs.sh as well as /usr/lib/qubes/init/setup-rwdev.sh.

-- Logs begin at Tue 2018-07-17 09:08:25 UTC, end at Tue 2018-07-17 09:10:20 UTC. --
Jul 17 09:10:20 host systemd[1]: Starting Initialize and mount /rw and /home...
Jul 17 09:10:20 host mount-dirs.sh[320]: + . /usr/lib/qubes/init/functions
Jul 17 09:10:20 host mount-dirs.sh[320]: + PROTECTED_FILE_LIST=/etc/qubes/protected-files.d
Jul 17 09:10:20 host mount-dirs.sh[320]: + set -e
Jul 17 09:10:20 host mount-dirs.sh[320]: + /usr/lib/qubes/init/setup-rwdev.sh
Jul 17 09:10:20 host mount-dirs.sh[320]: + set -e
Jul 17 09:10:20 host mount-dirs.sh[320]: + dev=/dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ -e /dev/xvdb ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + blockdev --getsz /dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: + private_size_512=4194304
Jul 17 09:10:20 host mount-dirs.sh[320]: + head -c 2147483648 /dev/zero
Jul 17 09:10:20 host mount-dirs.sh[320]: + diff /dev/xvdb -
Jul 17 09:10:20 host mount-dirs.sh[320]: head: error writing 'standard output': Broken pipe
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo Private device management: checking /dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: Private device management: checking /dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: + fsck.ext4 -p /dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: + content=/dev/xvdb: clean, 115/131072 files, 29042/524288 blocks
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo Private device management: fsck.ext4 of /dev/xvdb succeeded
Jul 17 09:10:20 host mount-dirs.sh[320]: Private device management: fsck.ext4 of /dev/xvdb succeeded
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ -e /dev/xvdb ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + mount /rw
Jul 17 09:10:20 host mount-dirs.sh[320]: + /usr/lib/qubes/init/setup-rw.sh
Jul 17 09:10:20 host mount-dirs.sh[320]: Checking /rw
Jul 17 09:10:20 host mount-dirs.sh[320]: Private device size management: enlarging /dev/xvdb
Jul 17 09:10:20 host mount-dirs.sh[320]: Private device size management: resize2fs of /dev/xvdb succeeded
Jul 17 09:10:20 host mount-dirs.sh[320]: Finished checking /rw
Jul 17 09:10:20 host mount-dirs.sh[320]: + initialize_home /rw/home ifneeded
Jul 17 09:10:20 host mount-dirs.sh[320]: + local home_root
Jul 17 09:10:20 host mount-dirs.sh[320]: + local mode
Jul 17 09:10:20 host mount-dirs.sh[320]: + local uid
Jul 17 09:10:20 host mount-dirs.sh[320]: + local gid
Jul 17 09:10:20 host mount-dirs.sh[320]: + local homedir
Jul 17 09:10:20 host mount-dirs.sh[320]: + local homedirwithouthome
Jul 17 09:10:20 host mount-dirs.sh[320]: + local pair
Jul 17 09:10:20 host mount-dirs.sh[320]: + local homedir_uid
Jul 17 09:10:20 host mount-dirs.sh[320]: + local homedir_gid
Jul 17 09:10:20 host mount-dirs.sh[320]: + local waitpid
Jul 17 09:10:20 host mount-dirs.sh[320]: + local waitpids
Jul 17 09:10:20 host mount-dirs.sh[320]: + home_root=/rw/home
Jul 17 09:10:20 host mount-dirs.sh[320]: + mode=ifneeded
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ -z /rw/home ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ ifneeded != unconditionally ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ ifneeded != ifneeded ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ -d /rw/home ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + awk -F : /\/home/ { print $1":"$3":"$4":"$6 }
Jul 17 09:10:20 host mount-dirs.sh[320]: + getent passwd
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo user:1000:1000:/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + awk -F :  { print $2 }
Jul 17 09:10:20 host mount-dirs.sh[320]: + uid=1000
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo user:1000:1000:/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + awk -F :  { print $3 }
Jul 17 09:10:20 host mount-dirs.sh[320]: + gid=1000
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo user:1000:1000:/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + awk -F :  { print $4 }
Jul 17 09:10:20 host mount-dirs.sh[320]: + homedir=/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + homedirwithouthome=user
Jul 17 09:10:20 host mount-dirs.sh[320]: + test -d /rw/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ ifneeded = unconditionally ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + waitpids=
Jul 17 09:10:20 host mount-dirs.sh[320]: + stat --format=%u /rw/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + homedir_uid=1000
Jul 17 09:10:20 host mount-dirs.sh[320]: + stat --format=%g /rw/home/user
Jul 17 09:10:20 host mount-dirs.sh[320]: + homedir_gid=1000
Jul 17 09:10:20 host mount-dirs.sh[320]: + [ 1000 -ne 1000 ]
Jul 17 09:10:20 host mount-dirs.sh[320]: + waitpids=
Jul 17 09:10:20 host mount-dirs.sh[320]: + echo Mounting /rw/home onto /home
Jul 17 09:10:20 host mount-dirs.sh[320]: Mounting /rw/home onto /home
Jul 17 09:10:20 host mount-dirs.sh[320]: + mount /home
Jul 17 09:10:20 host mount-dirs.sh[320]: + /usr/lib/qubes/init/bind-dirs.sh
Jul 17 09:10:20 host systemd[1]: Started Initialize and mount /rw and /home.

Culprit may be here...?

Jul 17 09:10:20 host mount-dirs.sh[320]: + head -c 2147483648 /dev/zero
Jul 17 09:10:20 host mount-dirs.sh[320]: + diff /dev/xvdb -
marmarek commented 6 years ago

Jul 17 08:43:36 host mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe

This is fine. It's about checking if xvdb require mkfs.

I guess the problem is caused by #1150 - the symlink was removed from template builder, but bind mount isn't part of qubes-core-agent 4.0.32, only 4.0.33 (just pushed to builders).

adrelanos commented 6 years ago

I am still having the old version from Qubes stable repository using if head -c $(( private_size_512 * 512 )) /dev/zero | diff "$dev" - >/dev/null; then. But with https://github.com/QubesOS/qubes-core-agent-linux/commit/8ff9cbe29970a9db2141d084b6db32b9323bf40e / https://github.com/QubesOS/updates-status/issues/572 that code will change. Jul 17 08:43:36 host mount-dirs.sh[295]: head: error writing 'standard output': Broken pipe is gone indeed after installing qubes-core-agent from Qubes tesitng repository. That path was a dead end though.

Original issue persists.

marmarek commented 6 years ago

https://github.com/QubesOS/updates-status/issues/593

adrelanos commented 6 years ago

https://github.com/QubesOS/updates-status/issues/593 fixes the issue.

marmarek commented 6 years ago

Do you have 3.2 with this template installed? I guess the same issue will apply there.

adrelanos commented 6 years ago

In R3.2 / Whonix 13 we don't depend on /usr/local.

In R3.2 / Whonix 14 (the referenced new builds) not yet tested.

adrelanos commented 6 years ago

Somehow USE_QUBES_REPO_TESTING = 1 (https://github.com/QubesOS/qubes-template-configs/pull/1) didn't work. In R3.2 / Whonix 14 /usr/local is still not persistent.

adrelanos commented 6 years ago

USE_QUBES_REPO_TESTING="" is being set.

2018-07-19 06:27:00.970091 +0000 build-fedora3: sudo env -i WHONIX_APT_REPOSITORY_OPTS="stable" WHONIX_ENABLE_TOR="0" WHONIX_DIR="/mnt/removable/qubes-src/Whonix" WHONIX_TBB_VERSION="" DIST="stretch" DISTRIBUTION="debian" TEMPLATE_SCRIPTS="/mnt/removable/qubes-src/builder-debian/template_debian" TEMPLATE_NAME="whonix-gw-14" TEMPLATE_FLAVOR="whonix-gateway" TEMPLATE_FLAVOR_DIR="+whonix-gateway:/mnt/removable/qubes-src/template-whonix +whonix-workstation:/mnt/removable/qubes-src/template-whonix" TEMPLATE_OPTIONS="minimal no-recommends" APPMENUS_DIR="/mnt/removable/qubes-src/template-whonix/" VERBOSE="2" DEBUG="" PATH="/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/user/.local/bin:/home/user/bin:/mnt/removable/qubes-src/builder-rpm/tools" BUILDER_DIR="/mnt/removable" SRC_DIR="qubes-src" DISCARD_PREPARED_IMAGE="" TEMPLATE_ROOT_WITH_PARTITIONS="" TEMPLATE_ROOT_SIZE="" USE_QUBES_REPO_VERSION="3.2" USE_QUBES_REPO_TESTING="" BUILDER_TURBO_MODE="1" REPO_PROXY="" FEDORA_MIRROR="" CENTOS_MIRROR="" EPEL_MIRROR="" QUBES_MIRROR="" \

https://github.com/QubesOS/qubes-template-configs/pull/1 was merged first. https://github.com/QubesOS/updates-status/issues/601 built after that. So the order of events was correct.

Any idea?

marmarek commented 6 years ago

config for R3.2 is separate, here: https://github.com/QubesOS/qubes-template-configs/blob/master/R3.2/templates-community/whonix-14.conf

adrelanos commented 6 years ago

Whonix templates built using USE_QUBES_REPO_TESTING = 1 now (https://github.com/QubesOS/updates-status/issues/609) but /usr/local still broken, therefore Tor config not persistent, therefore Whonix 14 release blocker.

user@host:~$ sudo journalctl -u qubes-mount-dirs.service 
-- Logs begin at Sat 2018-07-21 08:25:56 UTC, end at Sat 2018-07-21 08:32:08 UTC. --                                                                          
Jul 21 08:25:56 host systemd[1]: Starting Initialize and mount /rw and /home...                                                                               
Jul 21 08:25:56 host mount-dirs.sh[310]: Private device management: checking /dev/xvdb                                                                        
Jul 21 08:25:56 host mount-dirs.sh[310]: Private device management: fsck.ext4 of /dev/xvdb succeeded                                                          
Jul 21 08:25:56 host mount-dirs.sh[310]: Checking /rw                                                                                                         
Jul 21 08:25:56 host mount-dirs.sh[310]: Private device size management: enlarging /dev/xvdb                                                                  
Jul 21 08:25:56 host mount-dirs.sh[310]: Private device size management: resize2fs of /dev/xvdb succeeded                                                     
Jul 21 08:25:56 host mount-dirs.sh[310]: Finished checking /rw                                                                                                
Jul 21 08:25:56 host mount-dirs.sh[310]: Mounting /rw/home onto /home
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/spool/cron onto /var/spool/cron
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/lib/tor onto /var/lib/tor
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/lib/whonix onto /var/lib/whonix
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/lib/whonixcheck onto /var/lib/whonixcheck
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/cache/whonix-setup-wizard onto /var/cache/whonix-setup-wizard
Jul 21 08:25:56 host mount-dirs.sh[310]: Bind mounting /rw/bind-dirs/var/cache/anon-base-files onto /var/cache/anon-base-files
Jul 21 08:25:56 host systemd[1]: Started Initialize and mount /rw and /home.
user@host:~$ mount
/dev/mapper/dmroot on / type ext4 (rw,noatime,data=ordered)
/dev/xvdd on /lib/modules/4.14.41-1.pvops.qubes.x86_64 type ext3 (ro,relatime,data=ordered)
sysfs on /sys type sysfs (rw,relatime)
proc on /proc type proc (rw,relatime)
devtmpfs on /dev type devtmpfs (rw,nosuid,size=205424k,nr_inodes=51356,mode=755)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,size=1048576k,nr_inodes=53424)
devpts on /dev/pts type devpts (rw,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,nodev,size=213696k,nr_inodes=53424,mode=755)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k,nr_inodes=53424)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,size=213696k,nr_inodes=53424,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /sys/fs/cgroup/pids type cgroup (rw,nosuid,nodev,noexec,relatime,pids)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=33,pgrp=1,timeout=0,minproto=5,maxproto=5,direct)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
mqueue on /dev/mqueue type mqueue (rw,relatime)
xen on /proc/xen type xenfs (rw,relatime)
configfs on /sys/kernel/config type configfs (rw,relatime)
/dev/xvdb on /rw type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /home type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/spool/cron type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/tor type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/whonix type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/lib/whonixcheck type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/cache/whonix-setup-wizard type ext4 (rw,relatime,discard,data=ordered)
/dev/xvdb on /var/cache/anon-base-files type ext4 (rw,relatime,discard,data=ordered)
none on /run/msgcollector type tmpfs (rw,relatime,size=10240k,nr_inodes=53424)
tmpfs on /run/user/1000 type tmpfs (rw,nosuid,nodev,relatime,size=42736k,nr_inodes=53424,mode=700,uid=1000,gid=1000)
user@host:~$ mount | grep home
/dev/xvdb on /home type ext4 (rw,relatime,discard,data=ordered)
user@host:~$ mount | grep local
user@host:~$
adrelanos commented 6 years ago 
user@host:~$ cat /etc/fstab
# Accessible filesystems, by reference, are maintained under '/dev/disk'
# See man pages fstab(5), findfs(8), mount(8) and/or blkid(8) for more info
#
/dev/mapper/dmroot /                       ext4 defaults,noatime        1 1
/dev/xvdb               /rw                     auto    noauto,defaults,discard 1 2
/rw/home        /home       none    noauto,bind,defaults 0 0
/dev/xvdc1      swap                    swap    defaults        0 0
tmpfs                   /dev/shm                tmpfs   defaults,size=1G        0 0
devpts                  /dev/pts                devpts  gid=5,mode=620  0 0
sysfs                   /sys                    sysfs   defaults        0 0
proc                    /proc                   proc    defaults        0 0
xen                     /proc/xen               xenfs   defaults        0 0
/dev/xvdi       /mnt/removable  auto noauto,user,rw 0 0

/etc/fstab is missing /rw/usrlocal.

adrelanos commented 6 years ago 
user@host:~$ dpkg -l | grep qubes-core-agent
ii  qubes-core-agent                              3.2.30-1+deb9u1                            amd64        Qubes core agent
adrelanos commented 6 years ago

Somehow I downloaded not https://github.com/QubesOS/updates-status/issues/609 but an older template build.

adrelanos commented 6 years ago

Perhaps a template upload issue, reported here: https://github.com/QubesOS/qubes-issues/issues/3935#issuecomment-406782111

adrelanos commented 6 years ago

Closable.