search

QubesOS / qubes-issues

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

NFS mount through ConnectTCP delays shutdown #5911

Closed ardentbriar closed 1 year ago

ardentbriar commented 4 years ago

Qubes OS version

R4.0

Affected component(s) or functionality

NFS mount from another VM. Possibly related to ConnectTCP.

Brief summary

An NFS mount through a ConnectTCP bound port delays shutdown ~80-90 seconds.

To Reproduce

  1. On VM server set up an NFS mount.

Sharing to localhost exposes it to the bound port. Option insecure allows the client to use high ports. Use a root terminal.

# dnf install nfs-utils -y
# mkdir /data
# echo "C programmers never die. They are just cast into void." >/data/wisdom
# echo "/data localhost(rw,insecure)" >/etc/exports
# systemctl start nfs-server
  1. In dom0 allow VM client to bind to server.

NFS port is 2049.

$ echo "client @default allow,target=server" >>/etc/qubes-rpc/policy/qubes.ConnectTCP+2049
  1. On VM client bind port 2049.
# qvm-connect-tcp ::2049
Binding TCP '@default:2049' to 'localhost:2049'...
  1. On VM client mount NFS share.
# dnf install nfs-utils -y
# mkdir /mnt/data
# mount -t nfs localhost:/data /mnt/data
# cat /mnt/data/wisdom
C programmers never die. They are just cast into void.
  1. Shut down VM client.

Expected behavior

VM client shuts down quickly.

Actual behavior

The shutdown of VM client is delayed ~80-90 seconds.

Additional context

I think the delay is the NFS unmount timeout. A delay like this happens if the network goes down. I suspect what's happening is the bound port is unbound before the NFS unmount happens. So the connection is gone when the client tries to tell the server it's done.

Unmounting manually happens immediately. After a manual unmount shutdown happens quickly.

# umount /mnt/data

Solutions you've tried

Using the _netdev mount option in /etc/fstab. This treats the source as a network device and apparently keeps network up until unmount is complete. It shows the same behavior. Maybe the qubes port is unbound before the unmount starts, even though the network stack is still running.

Using a persistent bind through a systemd socket unit + mounting through a systemd mount unit, with various dependency orderings. Same behavior on everything I've tried.

Relevant documentation you've consulted

iamahuman commented 4 years ago

The qvm-connect-tcp shall run as a systemd job with the Qrexec daemon as a dependency AND the nfs mount as reverse dependency so that the nfs won't go stale before the mount could be torn down.

ardentbriar commented 4 years ago

Tried the ForceUnmount option in the systemd mount unit but no dice.

fepitre commented 4 years ago

Tried the ForceUnmount option in the systemd mount unit but no dice.

Have you tried to create a systemd service as described in section 4 of the documentation of ConnectTCP? That would go into the direction of @iamahuman's previous suggestion.

iamahuman commented 4 years ago

@fepitre I'm afraid those steps aren't enough; you would still have to specify all the forward and reverse dependencies for shutdown to work correctly.

As a side note, systemd-run lets you create and spin up an ephemeral unit w/o having to write a unit file.

ardentbriar commented 4 years ago

Yeah that's the way I did it. Here's a reproduction with the same environment.

To reproduce

  1. On server set up an NFS share.

  2. In dom0 allow client to bind to server.

  3. On client set up a persistent port binding as described in section 4.

The docs use /rw to bounce the data into the right place. You can also edit directly in a StandaloneVM.

Create /lib/systemd/system/data-server.socket:

[Unit]
Description=data-server

[Socket]
ListenStream=127.0.0.1:2049
Accept=true

[Install]
WantedBy=sockets.target

Create /lib/systemd/system/data-server@.service:

[Unit]
Description=data-server

[Service]
ExecStart=qrexec-client-vm '' qubes.ConnectTCP+2049
StandardInput=socket
StandardOutput=inherit
# systemctl daemon-reload
# systemctl start data-server.socket
# systemctl enable data-server.socket
  1. On client set up an NFS mount unit.

Create /etc/systemd/system/mnt-data.mount:

[Unit]
Description=/mnt/data
After=network.target

[Mount]
What=localhost:/data
Where=/mnt/data
Type=nfs
Options=_netdev,auto

[Install]
WantedBy=multi-user.target
# systemctl daemon-reload
# systemctl start mnt-data.mount
# systemctl enable mnt-data.mount
# cat /mnt/data/wisdom
C programmers never die. They are just cast into void.
  1. Shut down client.

Expected behavior

client shuts down quickly.

Actual behavior

The shutdown of client is delayed ~80-90 seconds.

Additional context

This works beautifully for setting it up. The socket is fired up at boot. The share is mounted and ready to use immediately. It's so close. But it causes that problem shutting down.

I've tried several different dependency setups. Getting the mount dependent on the socket with After=data-server.socket. There's an interesting remote-fs.target I poked around with, seemingly created by NFS. To no avail.

Does this implement the suggestion? I tried this in /lib/systemd/system/data-server.socket. It shows the same delay behavior.

[Unit]
Description=data-server
After=qubes-qrexec-agent.service
Before=mnt-data.mount

[Socket]
ListenStream=127.0.0.1:2049
Accept=true

[Install]
WantedBy=sockets.target
iamahuman commented 4 years ago

Before= and After= are order dependencies. You would still have to specify Wants= and WantedBy=.

[Unit]
Description=data-server
After=qubes-qrexec-agent.service
Wants=qubes-qrexec-agent.service
Before=mnt-data.mount

[Socket]
ListenStream=127.0.0.1:2049
Accept=true

[Install]
WantedBy=sockets.target
WantedBy=mnt-data.mount

Everything under the [Install] section is only applied when installing the unit, so make sure you regenerate the relevant symlinks with systemctl enable.

iamahuman commented 4 years ago

That said the qubes-qrexec-agent.service is better left in the service, not the socket.

ardentbriar commented 4 years ago

Thanks for that. I tried it out. I still show a delay with that setup + reenabling to get the symlinks right.

There is that separate data-server@.service, where it starts a new instance for every connection. I wonder if those get detached from the parent socket location in the dep chain. I tried putting some deps in there but it seemed to cause problems booting.

ardentbriar commented 4 years ago

Tried it with BindsTo for a stronger connection but there's still a delay. In mnt-data.mount:

[Unit]
Description=/mnt/data
After=network.target
BindsTo=data-server.socket

[Mount]
What=localhost:/data
Where=/mnt/data
Type=nfs
Options=_netdev,auto

[Install]
WantedBy=multi-user.target
iamahuman commented 4 years ago

Maybe the /var/log/xen/console/guest-<name>.log would be helpful

ardentbriar commented 4 years ago

Oh yeah, it shows it at the end. 91 second timeout.

There's that interesting remotefs target just before. Maybe I'll try connecting data-server@.service to it somehow.

[    0.000000] Linux version 4.19.125-1.pvops.qubes.x86_64 (user@build-fedora4) (gcc version 6.4.1 20170727 (Red Hat 6.4.1-1) (GCC)) #1 SMP Sat May 30 16:11:30 UTC 2020
[    0.000000] Command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 xen_scrub_pages=0 nopat
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
[    0.000000] x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64
[    0.000000] x86/fpu: Enabled xstate features 0x1f, context size is 960 bytes, using 'compacted' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000000a0000-0x00000000000fefff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000ff000-0x00000000000fffff] ACPI data
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000fa0003ff] usable
[    0.000000] BIOS-e820: [mem 0x00000000fc000000-0x00000000fc007fff] ACPI data
[    0.000000] x86/PAT: PAT support disabled.
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: Xen HVM
[    0.000000] Xen version 4.8.
[    0.106003] tsc: Fast TSC calibration failed
[    0.106005] tsc: Detected 3192.598 MHz processor
[    0.106153] last_pfn = 0xfa000 max_arch_pfn = 0x400000000
[    0.106193] Disabled
[    0.106203] CPU MTRRs all blank - virtualized system.
[    0.106205] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC  
[    0.117973] Using GB pages for direct mapping
[    0.118076] RAMDISK: [mem 0x02e2d000-0x03dc2fff]
[    0.118120] ACPI: Early table checksum verification disabled
[    0.118123] ACPI: RSDP 0x00000000000FFFC0 000024 (v02 Xen   )
[    0.118126] ACPI: XSDT 0x00000000FC007F70 000034 (v01 Xen    HVM      00000000 HVML 00000000)
[    0.118130] ACPI: FACP 0x00000000FC007D70 00010C (v05 Xen    HVM      00000000 HVML 00000000)
[    0.118134] ACPI: DSDT 0x00000000FC001050 006C9B (v05 Xen    HVM      00000000 INTL 20160831)
[    0.118137] ACPI: FACS 0x00000000FC001010 000040
[    0.118139] ACPI: FACS 0x00000000FC001010 000040
[    0.118141] ACPI: APIC 0x00000000FC007E80 00003C (v02 Xen    HVM      00000000 HVML 00000000)
[    0.118386] No NUMA configuration found
[    0.118387] Faking a node at [mem 0x0000000000000000-0x00000000f9ffffff]
[    0.118393] NODE_DATA(0) allocated [mem 0xf9fd5000-0xf9ffffff]
[    0.153036] Zone ranges:
[    0.153038]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.153039]   DMA32    [mem 0x0000000001000000-0x00000000f9ffffff]
[    0.153040]   Normal   empty
[    0.153041]   Device   empty
[    0.153041] Movable zone start for each node
[    0.153043] Early memory node ranges
[    0.153044]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.153045]   node   0: [mem 0x0000000000100000-0x00000000f9ffffff]
[    0.153249] Zeroed struct page in unavailable ranges: 24673 pages
[    0.153255] Initmem setup node 0 [mem 0x0000000000001000-0x00000000f9ffffff]
[    0.169961] ACPI: No IOAPIC entries present
[    0.169962] Using ACPI for processor (LAPIC) configuration information
[    0.169972] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[    0.169978] [mem 0xfc008000-0xffffffff] available for PCI devices
[    0.169979] Booting paravirtualized kernel on Xen PVH
[    0.169981] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.241295] random: get_random_bytes called from start_kernel+0xc3/0x76a with crng_init=0
[    0.241300] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:2 nr_node_ids:1
[    0.243076] percpu: Embedded 44 pages/cpu s143360 r8192 d28672 u1048576
[    0.243100] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.243107] Built 1 zonelists, mobility grouping on.  Total pages: 1007881
[    0.243108] Policy zone: DMA32
[    0.243109] Kernel command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 xen_scrub_pages=0 nopat
[    0.243130] You have booted with nomodeset. This means your GPU drivers are DISABLED
[    0.243130] Any video related functionality will be severely degraded, and you may not even be able to suspend the system properly
[    0.243131] Unless you actually understand what nomodeset does, you should reboot without enabling it
[    0.249133] Memory: 3982488K/4095612K available (12300K kernel code, 1486K rwdata, 3892K rodata, 2656K init, 4404K bss, 113124K reserved, 0K cma-reserved)
[    0.249285] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.249295] Kernel/User page tables isolation: enabled
[    0.249328] ftrace: allocating 38262 entries in 150 pages
[    0.259260] rcu: Hierarchical RCU implementation.
[    0.259262] rcu:     RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=2.
[    0.259262]  Tasks RCU enabled.
[    0.259263] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[    0.260833] Using NULL legacy PIC
[    0.260834] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 0
[    0.260846] xen:events: Using FIFO-based ABI
[    0.260851] xen:events: Xen HVM callback vector for event delivery is enabled
[    0.260856] rcu:     Offload RCU callbacks from CPUs: (none).
[    0.260887] Console: colour dummy device 80x25
[    0.261713] console [hvc0] enabled
[    0.261730] ACPI: Core revision 20180810
[    0.261769] ACPI: setting ELCR to 0200 (from ffff)
[    0.261798] Failed to register legacy timer interrupt
[    0.261814] APIC: Switch to symmetric I/O mode setup
[    0.261824] x2apic: IRQ remapping doesn't support X2APIC mode
[    0.261960] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2e04f9a571c, max_idle_ns: 440795365149 ns
[    0.261989] Calibrating delay loop (skipped), value calculated using timer frequency.. 6385.19 BogoMIPS (lpj=3192598)
[    0.262006] pid_max: default: 32768 minimum: 301
[    0.262033] Security Framework initialized
[    0.262041] Yama: becoming mindful.
[    0.262050] AppArmor: AppArmor disabled by boot time parameter
[    0.262977] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.262977] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.262977] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.262977] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.262977] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8
[    0.262977] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
[    0.262977] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.262977] Spectre V2 : Mitigation: Full generic retpoline
[    0.262977] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.262977] Spectre V2 : Enabling Restricted Speculation for firmware calls
[    0.262977] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.262977] Spectre V2 : User space: Mitigation: STIBP via seccomp and prctl
[    0.262977] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.262977] TAA: Mitigation: Clear CPU buffers
[    0.262977] MDS: Mitigation: Clear CPU buffers
[    0.262977] Freeing SMP alternatives memory: 32K
[    0.262977] clocksource: xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.262977] installing Xen timer for CPU 0
[    0.262977] smpboot: CPU0: Intel(R) Core(TM) i7-8700 CPU @ 3.20GHz (family: 0x6, model: 0x9e, stepping: 0xa)
[    0.262977] cpu 0 spinlock event irq 5
[    0.262977] Performance Events: unsupported p6 CPU model 158 no PMU driver, software events only.
[    0.262977] rcu: Hierarchical SRCU implementation.
[    0.262977] random: crng done (trusting CPU's manufacturer)
[    0.262977] NMI watchdog: Perf NMI watchdog permanently disabled
[    0.262977] smp: Bringing up secondary CPUs ...
[    0.263048] installing Xen timer for CPU 1
[    0.263117] x86: Booting SMP configuration:
[    0.263126] .... node  #0, CPUs:      #1
[    0.263570] cpu 1 spinlock event irq 11
[    0.263570] smp: Brought up 1 node, 2 CPUs
[    0.263570] smpboot: Max logical packages: 1
[    0.263570] smpboot: Total of 2 processors activated (12770.39 BogoMIPS)
[    0.263992] devtmpfs: initialized
[    0.264019] x86/mm: Memory block size: 128MB
[    0.264326] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.264326] futex hash table entries: 512 (order: 3, 32768 bytes)
[    0.264326] pinctrl core: initialized pinctrl subsystem
[    0.284719] RTC time: 165:165:165, date: 165/165/65
[    0.284919] NET: Registered protocol family 16
[    0.284939] xen:grant_table: Grant tables using version 1 layout
[    0.284964] Grant table initialized
[    0.285039] audit: initializing netlink subsys (disabled)
[    0.285080] audit: type=2000 audit(1593344666.798:1): state=initialized audit_enabled=0 res=1
[    0.285080] cpuidle: using governor menu
[    0.285097] ACPI: bus type PCI registered
[    0.285170] PCI: Fatal: No config space access function found
[    0.286721] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.286721] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.287028] cryptd: max_cpu_qlen set to 1000
[    0.287047] ACPI: Added _OSI(Module Device)
[    0.287048] ACPI: Added _OSI(Processor Device)
[    0.287057] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.287066] ACPI: Added _OSI(Processor Aggregator Device)
[    0.287076] ACPI: Added _OSI(Linux-Dell-Video)
[    0.287085] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.289390] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.289592] ACPI: SCI (ACPI GSI 9) not registered
[    0.292609] ACPI: Interpreter enabled
[    0.292619] ACPI: (supports S0)
[    0.292627] ACPI: Using platform specific model for interrupt routing
[    0.292645] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.292765] ACPI: Enabled 1 GPEs in block 00 to 0F
[    0.292997] ACPI Error: No handler or method for GPE 00, disabling event (20180810/evgpe-841)
[    0.293023] ACPI Error: No handler or method for GPE 01, disabling event (20180810/evgpe-841)
[    0.293054] ACPI Error: No handler or method for GPE 03, disabling event (20180810/evgpe-841)
[    0.293077] ACPI Error: No handler or method for GPE 04, disabling event (20180810/evgpe-841)
[    0.293099] ACPI Error: No handler or method for GPE 05, disabling event (20180810/evgpe-841)
[    0.293120] ACPI Error: No handler or method for GPE 06, disabling event (20180810/evgpe-841)
[    0.293143] ACPI Error: No handler or method for GPE 07, disabling event (20180810/evgpe-841)
[    0.296982] xen:balloon: Initialising balloon driver
[    0.302983] vgaarb: loaded
[    0.303095] SCSI subsystem initialized
[    0.303176] ACPI: bus type USB registered
[    0.303202] usbcore: registered new interface driver usbfs
[    0.303217] usbcore: registered new interface driver hub
[    0.303241] usbcore: registered new device driver usb
[    0.303266] pps_core: LinuxPPS API ver. 1 registered
[    0.303278] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.303300] PTP clock support registered
[    0.303337] EDAC MC: Ver: 3.0.0
[    0.304001] PCI: Using ACPI for IRQ routing
[    0.304011] PCI: System does not support PCI
[    0.304100] NetLabel: Initializing
[    0.304110] NetLabel:  domain hash size = 128
[    0.304122] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.304144] NetLabel:  unlabeled traffic allowed by default
[    0.306615] clocksource: Switched to clocksource xen
[    0.321339] VFS: Disk quotas dquot_6.6.0
[    0.321366] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.321429] pnp: PnP ACPI init
[    0.321466] pnp: PnP ACPI: found 0 devices
[    0.326632] NET: Registered protocol family 2
[    0.326848] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes)
[    0.326892] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.327118] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    0.327600] TCP: Hash tables configured (established 32768 bind 32768)
[    0.327789] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    0.327881] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    0.327992] NET: Registered protocol family 1
[    0.328012] NET: Registered protocol family 44
[    0.328043] Unpacking initramfs...
[    0.342501] Freeing initrd memory: 15960K
[    0.348467] Initialise system trusted keyrings
[    0.348485] Key type blacklist registered
[    0.348644] workingset: timestamp_bits=36 max_order=20 bucket_order=0
[    0.351309] zbud: loaded
[    0.582339] alg: No test for 842 (842-generic)
[    0.582372] alg: No test for 842 (842-scomp)
[    0.585957] NET: Registered protocol family 38
[    0.585974] Key type asymmetric registered
[    0.585995] Asymmetric key parser 'x509' registered
[    0.586016] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 244)
[    0.586072] io scheduler noop registered
[    0.586083] io scheduler deadline registered
[    0.586121] io scheduler cfq registered (default)
[    0.586134] io scheduler mq-deadline registered
[    0.586428] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    0.587053] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    0.587923] Non-volatile memory driver v1.3
[    0.587951] Linux agpgart interface v0.103
[    0.588564] libphy: Fixed MDIO Bus: probed
[    0.588633] usbcore: registered new interface driver usbserial_generic
[    0.588650] usbserial: USB Serial support registered for generic
[    0.588672] i8042: PNP: No PS/2 controller found.
[    0.588733] mousedev: PS/2 mouse device common for all mice
[    0.588784] device-mapper: uevent: version 1.0.3
[    0.588828] device-mapper: ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-devel@redhat.com
[    0.588894] hidraw: raw HID events driver (C) Jiri Kosina
[    0.588926] usbcore: registered new interface driver usbhid
[    0.588938] usbhid: USB HID core driver
[    0.588995] drop_monitor: Initializing network drop monitor service
[    0.589163] Initializing XFRM netlink socket
[    0.589237] NET: Registered protocol family 10
[    0.590622] Segment Routing with IPv6
[    0.590660] mip6: Mobile IPv6
[    0.590670] NET: Registered protocol family 17
[    0.591192] mce: Using 2 MCE banks
[    0.591215] RAS: Correctable Errors collector initialized.
[    0.591241] AVX2 version of gcm_enc/dec engaged.
[    0.591253] AES CTR mode by8 optimization enabled
[    0.597918] sched_clock: Marking stable (595867250, 1116098)->(966180326, -369196978)
[    0.598157] registered taskstats version 1
[    0.598172] Loading compiled-in X.509 certificates
[    0.598195] zswap: loaded using pool lzo/zbud
[    0.600465] Key type big_key registered
[    0.601517] Key type encrypted registered
[    0.601532] ima: No TPM chip found, activating TPM-bypass!
[    0.601547] ima: Allocated hash algorithm: sha1
[    0.601660] xenbus_probe_frontend: Device with no driver: device/vbd/51712
[    0.601675] xenbus_probe_frontend: Device with no driver: device/vbd/51728
[    0.601689] xenbus_probe_frontend: Device with no driver: device/vbd/51744
[    0.601703] xenbus_probe_frontend: Device with no driver: device/vbd/51760
[    0.601717] xenbus_probe_frontend: Device with no driver: device/vif/0
[    0.601742]   Magic number: 1:252:3141
[    0.601785] hctosys: unable to open rtc device (rtc0)
[    0.602791] Freeing unused decrypted memory: 2040K
[    0.603989] Freeing unused kernel image memory: 2656K
[    0.815019] Write protecting the kernel read-only data: 18432k
[    0.815391] Freeing unused kernel image memory: 2024K
[    0.815471] Freeing unused kernel image memory: 204K
[    0.815511] rodata_test: all tests were successful
[    0.815525] Run /init as init process
Qubes initramfs script here:
[    0.822309] Invalid max_queues (4), will use default max: 2.
[    1.109938] blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.113190]  xvda: xvda1 xvda2 xvda3
[    1.116138] blkfront: xvdb: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.166135] blkfront: xvdc: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.196965] blkfront: xvdd: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Waiting for /dev/xvda* devices...
Qubes: Doing R/W setup for TemplateVM...
[    1.310305]  xvdc: xvdc1 xvdc3
Setting up swapspace version 1, size = 1024 MiB (1073737728 bytes)
no label, UUID=af4c9174-7e60-44a9-b44d-b21b5e6d2d33
Qubes: done.
[    1.381995] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2e04f9a571c, max_idle_ns: 440795365149 ns
[    1.526929] EXT4-fs (xvda3): mounted filesystem with ordered data mode. Opts: (null)
Waiting for /dev/xvdd device...
mount: /dev/xvdd is write-protected, mounting read-only
[    1.533928] EXT4-fs (xvdd): mounting ext3 file system using the ext4 subsystem
[    1.540100] EXT4-fs (xvdd): mounted filesystem with ordered data mode. Opts: (null)
[    2.694806] EXT4-fs (xvda3): re-mounted. Opts: (null)
switch_root: failed to mount moving /dev to /sysroot/dev: Invalid argument
switch_root: forcing unmount of /dev
switch_root: failed to mount moving /proc to /sysroot/proc: Invalid argument
switch_root: forcing unmount of /proc
switch_root: failed to mount moving /sys to /sysroot/sys: Invalid argument
switch_root: forcing unmount of /sys
switch_root: failed to mount moving /run to /sysroot/run: Invalid argument
switch_root: forcing unmount of /run
[    2.801957] systemd[1]: systemd v243.8-1.fc31 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[    2.802165] systemd[1]: Detected virtualization xen.
[    2.802196] systemd[1]: Detected architecture x86-64.

Welcome to .[0;34mFedora 31 (Thirty One).[0m!

[    2.804014] systemd[1]: No hostname configured.
[    2.804044] systemd[1]: Set hostname to <localhost>.
[    2.987184] systemd[1]: /usr/lib/systemd/system/qubes-meminfo-writer.service:8: PIDFile= references a path below legacy directory /var/run/, updating /var/run/meminfo-writer.pid → /run/meminfo-writer.pid; please update the unit file accordingly.
[    3.061946] systemd[1]: /usr/lib/systemd/system/cups.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/cups/cups.sock → /run/cups/cups.sock; please update the unit file accordingly.
[    3.068641] systemd[1]: Created slice system-getty.slice.
[.[0;32m  OK  .[0m] Created slice .[0;1;39msystem-getty.slice.[0m.
[    3.069510] systemd[1]: Created slice system-serial\x2dgetty.slice.
[.[0;32m  OK  .[0m] Created slice .[0;1;39msystem-serial\x2dgetty.slice.[0m.
[    3.069780] systemd[1]: Created slice User and Session Slice.
[.[0;32m  OK  .[0m] Created slice .[0;1;39mUser and Session Slice.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mDispatch Password …ts to Console Directory Watch.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mForward Password R…uests to Wall Directory Watch.[0m.
[.[0;32m  OK  .[0m] Set up automount .[0;1;39mArbitrary…s File System Automount Point.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mLocal Encrypted Volumes.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSlices.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mProcess Core Dump Socket.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39minitctl Compatibility Named Pipe.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mJournal Audit Socket.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mJournal Socket (/dev/log).[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mJournal Socket.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mudev Control Socket.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mudev Kernel Socket.[0m.
         Mounting .[0;1;39mHuge Pages File System.[0m...
         Mounting .[0;1;39mPOSIX Message Queue File System.[0m...
         Mounting .[0;1;39m/proc/xen.[0m...
         Mounting .[0;1;39mKernel Debug File System.[0m...
         Starting .[0;1;39mCreate list of st…odes for the current kernel.[0m...
         Starting .[0;1;39mPreprocess NFS configuration convertion.[0m...
         Starting .[0;1;39mFile System Check on Root Device.[0m...
         Starting .[0;1;39mLoad Kernel Modules.[0m...
         Starting .[0;1;39mudev Coldplug all Devices.[0m...
[.[0;32m  OK  .[0m] Mounted .[0;1;39mHuge Pages File System.[0m.
[.[0;32m  OK  .[0m] Mounted .[0;1;39mPOSIX Message Queue File System.[0m.
[.[0;32m  OK  .[0m] Mounted .[0;1;39mKernel Debug File System.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mCreate list of sta… nodes for the current kernel.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mPreprocess NFS configuration convertion.[0m.
[    3.133035] xen:xen_evtchn: Event-channel device installed
[.[0;32m  OK  .[0m] Mounted .[0;1;39m/proc/xen.[0m.
[    3.143131] u2mfn: loading out-of-tree module taints kernel.
[.[0;32m  OK  .[0m] Started .[0;1;39mLoad Kernel Modules.[0m.
         Mounting .[0;1;39mKernel Configuration File System.[0m...
         Starting .[0;1;39mQubes DB agent.[0m...
         Starting .[0;1;39mApply Kernel Variables.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mFile System Check on Root Device.[0m.
[.[0;32m  OK  .[0m] Mounted .[0;1;39mKernel Configuration File System.[0m.
         Starting .[0;1;39mRemount Root and Kernel File Systems.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mApply Kernel Variables.[0m.
[    3.180282] EXT4-fs (xvda3): re-mounted. Opts: discard
[.[0;32m  OK  .[0m] Started .[0;1;39mRemount Root and Kernel File Systems.[0m.
         Starting .[0;1;39mCreate Static Device Nodes in /dev.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes DB agent.[0m.
         Starting .[0;1;39mInit Qubes Services settings.[0m...
         Starting .[0;1;39mLoad/Save Random Seed.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mudev Coldplug all Devices.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mLoad/Save Random Seed.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mCreate Static Device Nodes in /dev.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mLocal File Systems (Pre).[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mEntropy Daemon based on the HAVEGE algorithm.[0m.
         Starting .[0;1;39mJournal Service.[0m...
         Starting .[0;1;39mudev Kernel Device Manager.[0m...
[    3.516541] systemd: 56 output lines suppressed due to ratelimiting
[    3.520106] systemd[1]: systemd v243.8-1.fc31 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[    3.520180] systemd[1]: Detected virtualization xen.
[    3.520192] systemd[1]: Detected architecture x86-64.
[    3.635325] systemd[1]: /usr/lib/systemd/system/qubes-meminfo-writer.service:8: PIDFile= references a path below legacy directory /var/run/, updating /var/run/meminfo-writer.pid → /run/meminfo-writer.pid; please update the unit file accordingly.
[    3.677488] systemd[1]: /usr/lib/systemd/system/cups.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/cups/cups.sock → /run/cups/cups.sock; please update the unit file accordingly.
[    3.724077] systemd[1]: Started Init Qubes Services settings.
[.[0;32m  OK  .[0m] Started .[0;1;39mInit Qubes Services settings.[0m.
[    3.724688] systemd[1]: Starting Initialize and mount /rw and /home...
         Starting .[0;1;39mInitialize and mount /rw and /home.[0m...
[    3.725191] systemd[1]: Starting Adjust root filesystem size...
         Starting .[0;1;39mAdjust root filesystem size.[0m...
[    4.001784] systemd[1]: Started Journal Service.
[.[0;32m  OK  .[0m] Started .[0;1;39mJournal Service.[0m.
[    4.002348] audit: type=1130 audit(1593344670.514:2): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
         Starting .[0;1;39mFlush Journal to Persistent Storage.[0m...
[    4.002973] EXT4-fs (xvdb): mounted filesystem with ordered data mode. Opts: discard
[    4.009084] systemd-journald[246]: Received client request to flush runtime journal.
[.[0;32m  OK  .[0m] Started .[0;1;39mAdjust root filesystem size.[0m.
[    4.162279] audit: type=1130 audit(1593344670.675:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-rootfs-resize comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mInitialize and mount /rw and /home.[0m.
[    4.298331] audit: type=1130 audit(1593344670.811:4): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-mount-dirs comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mFlush Journal to Persistent Storage.[0m.
[    4.460230] audit: type=1130 audit(1593344670.973:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mudev Kernel Device Manager.[0m.
[    4.468845] audit: type=1130 audit(1593344670.981:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.555560] input: PC Speaker as /devices/platform/pcspkr/input/input0
[    4.572818] RAPL PMU: API unit is 2^-32 Joules, 5 fixed counters, 655360 ms ovfl timer
[    4.572838] RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
[    4.572849] RAPL PMU: hw unit of domain package 2^-14 Joules
[    4.572860] RAPL PMU: hw unit of domain dram 2^-14 Joules
[    4.572869] RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
[    4.572880] RAPL PMU: hw unit of domain psys 2^-14 Joules
[    4.586261] xen_netfront: Initialising Xen virtual ethernet driver
[.[0;32m  OK  .[0m] Found device .[0;1;39m/dev/hvc0.[0m.
[.[0;32m  OK  .[0m] Found device .[0;1;39m/dev/xvdc1.[0m.
         Activating swap .[0;1;39m/dev/xvdc1.[0m...
[    4.625667] Adding 1048572k swap on /dev/xvdc1.  Priority:-2 extents:1 across:1048572k SSFS
[.[0;32m  OK  .[0m] Activated swap .[0;1;39m/dev/xvdc1.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSwap.[0m.
         Mounting .[0;1;39mTemporary Directory (/tmp).[0m...
[.[0;32m  OK  .[0m] Mounted .[0;1;39mTemporary Directory (/tmp).[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mLocal File Systems.[0m.
         Starting .[0;1;39mRestore /run/initramfs on shutdown.[0m...
         Starting .[0;1;39mEarly Qubes VM settings.[0m...
         Starting .[0;1;39mCreate Volatile Files and Directories.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mRestore /run/initramfs on shutdown.[0m.
[    4.632398] audit: type=1130 audit(1593344671.145:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.652423] intel_rapl: Found RAPL domain package
[    4.652436] intel_rapl: Found RAPL domain core
[[    4.652452] i.[0;32m  OK  .[0mntel_rapl: Found RAPL domain unc] ore
Started .[0;1;39mCreate Volatile Files and Directories.[0m.
[    4.652463] intel_rapl: Found RAPL domain dram
[.[0;32m  OK  .[0m] Started .[0;1;39mEarly Qubes VM settings.[0m.
[    4.652879] audit: type=1130 audit(1593344671.165:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.652911] audit: type=1130 audit(1593344671.165:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-early-vm-config comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
         Mounting .[0;1;39mRPC Pipe File System.[0m...
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSystem Time Set.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSystem Time Synchronized.[0m.
         Starting .[0;1;39mUpdate UTMP about System Boot/Shutdown.[0m...
[    4.659717] audit: type=1127 audit(1593344671.171:10): pid=383 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mUpdate UTMP about System Boot/Shutdown.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSystem Initialization.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mCUPS Scheduler.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mUpdate system time each 6h.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mPeriodically check for updates.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mDaily Cleanup of Temporary Directories.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mdaily update of the root trust anchor for DNSSEC.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mPaths.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mTimers.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mCUPS Scheduler.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mdata-server.[0m.
[.[0;32m  OK  .[0m] Listening on .[0;1;39mD-Bus System Message Bus Socket.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mSockets.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mBasic System.[0m.
         Starting .[0;1;39mGSSAPI Proxy Daemon.[0m...
         Starting .[0;1;39mQubes base firewall settings.[0m...
         Starting .[0;1;39mQubes memory information reporter.[0m...
         Starting .[0;1;39mLogin Service.[0m...
         Starting .[0;1;39mXen driver domain device daemon.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes memory information reporter.[0m.
         Starting .[0;1;39mQubes GUI Agent.[0m...
[    4.779677] RPC: Registered named UNIX socket transport module.
[    4.779690] RPC: Registered udp transport module.
[    4.779699] RPC: Registered tcp transport module.
[    4.779708] RPC: Registered tcp NFSv4.1 backchannel transport module.
[.[0;32m  OK  .[0m] Mounted .[0;1;39mRPC Pipe File System.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mrpc_pipefs.target.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mGSSAPI Proxy Daemon.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mXen driver domain device daemon.[0m.
         Starting .[0;1;39mQubes remote exec agent.[0m...
[.[0;32m  OK  .[0m] Reached target .[0;1;39mNFS client services.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mRemote File Systems (Pre).[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes GUI Agent.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes remote exec agent.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes base firewall settings.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mNetwork.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mNetwork is Online.[0m.
         Mounting .[0;1;39m/mnt/data.[0m...
         Starting .[0;1;39mCUPS Scheduler.[0m...
         Starting .[0;1;39mQubes misc post-boot actions.[0m...
         Starting .[0;1;39mNotify NFS peers of a restart.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mNotify NFS peers of a restart.[0m.
[    4.870382] FS-Cache: Loaded
[    4.880715] FS-Cache: Netfs 'nfs' registered for caching
         Starting .[0;1;39mD-Bus System Message Bus.[0m...
[    4.897053] Key type dns_resolver registered
[    4.907148] NFS: Registering the id_resolver key type
[    4.907166] Key type id_resolver registered
[    4.907173] Key type id_legacy registered
[.[0;32m  OK  .[0m] Created slice .[0;1;39msystem-data\x2dserver.slice.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mdata-server (127.0.0.1:785).[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mD-Bus System Message Bus.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mQubes misc post-boot actions.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mCUPS Scheduler.[0m.
[.[0;32m  OK  .[0m] Mounted .[0;1;39m/mnt/data.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mRemote File Systems.[0m.
         Starting .[0;1;39mPermit User Sessions.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mPermit User Sessions.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mGetty on tty1.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mSerial Getty on hvc0.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mLogin Prompts.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mLogin Service.[0m.
[    5.339410] kauditd_printk_skb: 32 callbacks suppressed
[    5.339411] audit: type=1100 audit(1593344671.852:33): pid=547 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_rootok acct="user" exe="/usr/bin/qubes-gui-runuser" hostname=client addr=? terminal=/dev/tty7 res=success'
[    5.340287] audit: type=1130 audit(1593344671.853:34): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-logind comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.343281] audit: type=1103 audit(1593344671.856:35): pid=547 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/bin/qubes-gui-runuser" hostname=client addr=? terminal=/dev/tty7 res=success'
[.[0;32m  OK  .[0m] Created slice .[0;1;39mUser Slice of UID 1000.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mMulti-User System.[0m.
         Starting .[0;1;39mUpdate UTMP about System Runlevel Changes.[0m...
         Starting .[0;1;39mUser Runtime Directory /run/user/1000.[0m...
[.[0;32m  OK  .[0m] Started .[0;1;39mUser Runtime Directory /run/user/1000.[0m.
[    5.357976] audit: type=1130 audit(1593344671.870:36): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user-runtime-dir@1000 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
         Starting .[0;1;39mUser Manager for UID 1000.[0m...
[    5.359523] audit: type=1129 audit(1593344671.872:37): pid=614 uid=0 auid=4294967295 ses=4294967295 msg='old-level=N new-level=3 comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mUpdate UTMP about System Runlevel Changes.[0m.
[    5.361201] audit: type=1130 audit(1593344671.874:38): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp-runlevel comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.361235] audit: type=1131 audit(1593344671.874:39): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp-runlevel comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.365306] audit: type=1101 audit(1593344671.878:40): pid=617 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_unix acct="user" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.365414] audit: type=1006 audit(1593344671.878:41): pid=617 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=1 res=1
[    5.365581] audit: type=1105 audit(1593344671.878:42): pid=617 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_selinux,pam_selinux,pam_loginuid,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="user" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Started .[0;1;39mUser Manager for UID 1000.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mSession c1 of user user.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mSession c2 of user user.[0m.
[    5.588033] fbcon: Taking over console
[    6.586003] fuse init (API version 7.27)

Fedora 31 (Thirty One)
Kernel 4.19.125-1.pvops.qubes.x86_64 on an x86_64 (hvc0)

client login: [   16.882773] kauditd_printk_skb: 15 callbacks suppressed
[   16.882774] audit: type=1130 audit(1593344683.395:58): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-sync-time comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   16.983752] audit: type=1106 audit(1593344683.496:59): pid=897 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
[   16.983799] audit: type=1104 audit(1593344683.496:60): pid=897 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
         Stopping .[0;1;39mSession c2 of user user.[0m.
         Stopping .[0;1;39mSession c3 of user root.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mMulti-User System.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mLogin Prompts.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mrpc_pipefs.target.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mTimers.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mPeriodically check for updates.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mDaily Cleanup of Temporary Directories.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mdaily update of the root trust anchor for DNSSEC.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mSystem Time Synchronized.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mSystem Time Set.[0m.
         Unmounting .[0;1;39mRPC Pipe File System.[0m...
         Stopping .[0;1;39mCUPS Scheduler.[0m...
         Stopping .[0;1;39mdata-server (127.0.0.1:785).[0m...
         Stopping .[0;1;39mRestore /run/initramfs on shutdown.[0m...
         Stopping .[0;1;39mGetty on tty1.[0m...
         Stopping .[0;1;39mAuthorization Manager.[0m...
         Stopping .[0;1;39mQubes GUI Agent.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mQubes base firewall settings.[0m.
[   16.996709] audit: type=1131 audit(1593344683.509:61): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-iptables comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
         Stopping .[0;1;39mQubes misc post-boot actions.[0m...
         Stopping .[0;1;39mUpdate time from ClockVM.[0m...
         Stopping .[0;1;39mRealtimeKit Scheduling Policy Service.[0m...
         Stopping .[0;1;39mSerial Getty on hvc0.[0m...
         Stopping .[0;1;39mLoad/Save Random Seed.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mdata-server (127.0.0.1:785).[0m.
[   17.017513] audit: type=1131 audit(1593344683.530:62): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=data-server@0-127.0.0.1:2049-127.0.0.1:785 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Stopped .[0;1;39mGetty on tty1.[0m.
[   17.019962] audit: type=1131 audit(1593344683.532:63): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Stopped .[0;1;39mRealtimeKit Scheduling Policy Service.[0m.
[   17.024415] audit: type=1131 audit(1593344683.537:64): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rtkit-daemon comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Stopped .[0;1;39mAuthorization Manager.[0m.
[   17.028624] audit: type=1131 audit(1593344683.541:65): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=polkit comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUpdate time from ClockVM.[0m.
[   17.033877] audit: type=1131 audit(1593344683.546:66): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=qubes-sync-time comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Unmounted .[0;1;39mRPC Pipe File System.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mRestore /run/initramfs on shutdown.[0m.
[   17.042497] audit: type=1131 audit(1593344683.555:67): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[.[0;32m  OK  .[0m] Stopped .[0;1;39mCUPS Scheduler.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mQubes misc post-boot actions.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mSession c3 of user root.[0m.
[.[0;32m  OK  .[0m] Removed slice .[0;1;39msystem-data\x2dserver.slice.[0m.
[   17.109736] u2mfn_release, priv=          (null)
[.[0;32m  OK  .[0m] Removed slice .[0;1;39msystem-getty.slice.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUpdate system time each 6h.[0m.
         Stopping .[0;1;39mQubes remote exec agent.[0m...
         Stopping .[0;1;39mUser Manager for UID 0.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mQubes remote exec agent.[0m.
         Stopping .[0;1;39mXen driver domain device daemon.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mXen driver domain device daemon.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mSerial Getty on hvc0.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mQubes GUI Agent.[0m.
[.[0;32m  OK  .[0m] Removed slice .[0;1;39msystem-serial\x2dgetty.slice.[0m.
         Stopping .[0;1;39mQubes memory information reporter.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mQubes memory information reporter.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUser Manager for UID 0.[0m.
         Stopping .[0;1;39mUser Runtime Directory /run/user/0.[0m...
[.[0;32m  OK  .[0m] Unmounted .[0;1;39m/run/user/0.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUser Runtime Directory /run/user/0.[0m.
[.[0;32m  OK  .[0m] Removed slice .[0;1;39mUser Slice of UID 0.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mLoad/Save Random Seed.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mSession c2 of user user.[0m.
         Stopping .[0;1;39mLogin Service.[0m...
         Stopping .[0;1;39mUser Manager for UID 1000.[0m...
[.[0;32m  OK  .[0m] Unmounted .[0;1;39m/run/user/1000/gvfs.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mLogin Service.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUser Manager for UID 1000.[0m.
         Stopping .[0;1;39mUser Runtime Directory /run/user/1000.[0m...
[.[0;32m  OK  .[0m] Unmounted .[0;1;39m/run/user/1000.[0m.
[.[0;32m  OK  .[0m] Stopped .[0;1;39mUser Runtime Directory /run/user/1000.[0m.
[.[0;32m  OK  .[0m] Removed slice .[0;1;39mUser Slice of UID 1000.[0m.
         Stopping .[0;1;39mPermit User Sessions.[0m...
[.[0;32m  OK  .[0m] Stopped .[0;1;39mPermit User Sessions.[0m.
[.[0;32m  OK  .[0m] Stopped target .[0;1;39mRemote File Systems.[0m.
         Unmounting .[0;1;39m/mnt/data.[0m...
[.[0m.[0;31m*     .[0m] A stop job is running for /mnt/data (6s / 1min 31s)
.M
.[K[.[0;1;31m*.[0m.[0;31m*    .[0m] A stop job is running for /mnt/data (6s / 1min 31s)
.M
.[K[.[0;31m*.[0;1;31m*.[0m.[0;31m*   .[0m] A stop job is running for /mnt/data (7s / 1min 31s)
.M
.[K[ .[0;31m*.[0;1;31m*.[0m.[0;31m*  .[0m] A stop job is running for /mnt/data (8s / 1min 31s)
.M
.[K[  .[0;31m*.[0;1;31m*.[0m.[0;31m* .[0m] A stop job is running for /mnt/data (8s / 1min 31s)
.M
.[K[   .[0;31m*.[0;1;31m*.[0m.[0;31m*.[0m] A stop job is running for /mnt/data (9s / 1min 31s)
.M
.[K[    .[0;31m*.[0;1;31m*.[0m] A stop job is running for /mnt/data (9s / 1min 31s)
.M
.[K[     .[0;31m*.[0m] A stop job is running for /mnt/data (10s / 1min 31s)
.M
.[K[    .[0;31m*.[0;1;31m*.[0m] A stop job is running for /mnt/data (10s / 1min 31s)
.M
.[K[   .[0;31m*.[0;1;31m*.[0m.[0;31m*.[0m] A stop job is running for /mnt/data (11s / 1min 31s)
.M
.[K[  .[0;31m*.[0;1;31m*.[0m.[0;31m* .[0m] A stop job is running for /mnt/data (12s / 1min 31s)
.M
.[K[ .[0;31m*.[0;1;31m*.[0m.[0;31m*  .[0m] A stop job is running for /mnt/data (12s / 1min 31s)
.M
.[K[.[0;31m*.[0;1;31m*.[0m.[0;31m*   .[0m] A stop job is running for /mnt/data (13s / 1min 31s)
.M
.[K[.[0;1;31m*.[0m.[0;31m*    .[0m] A stop job is running for /mnt/data (13s / 1min 31s)
.M
.[K[.[0m.[0;31m*     .[0m] A stop job is running for /mnt/data (14s / 1min 31s)
.M
.[K[.[0;1;31m*.[0m.[0;31m*    .[0m] A stop job is running for /mnt/data (14s / 1min 31s)
.M
.[K[.[0;31m*.[0;1;31m*.[0m.[0;31m*   .[0m] A stop job is running for /mnt/data (15s / 1min 31s)
.M
.[K[ .[0;31m*.[0;1;31m*.[0m.[0;31m*  .[0m] A stop job is running for /mnt/data (16s / 1min 31s)
.M
.[K[  .[0;31m*.[0;1;31m*.[0m.[0;31m* .[0m] A stop job is running for /mnt/data (16s / 1min 31s)
.M
.[K[   .[0;31m*.[0;1;31m*.[0m.[0;31m*.[0m] A stop job is running for /mnt/data (17s / 1min 31s)
.M
.[K[    .[0;31m*.[0;1;31m*.[0m] A stop job is running for /mnt/data (17s / 1min 31s)
.M
.[K[     .[0;31m*.[0m] A stop job is running for /mnt/data (18s / 1min 31s)
.M
.[K[    .[0;31m*.[0;1;31m*.[0m] A stop job is running for /mnt/data (18s / 1min 31s)
.M
.[K[   .[0;31m*.[0;1;31m*.[0m.[0;31m*.[0m] A stop job is running for /mnt/data (19s / 1min 31s)
.M
.[K[  .[0;31m*.[0;1;31m*.[0m.[0;31m* .[0m] A stop job is running for /mnt/data (20s / 1min 31s)
.M
.[K[ .[0;31m*.[0;1;31m*.[0m.[0;31m*  .[0m] A stop job is running for /mnt/data (20s / 1min 31s)
.M
.[K[.[0;31m*.[0;1;31m*.[0m.[0;31m*   .[0m] A stop job is running for /mnt/data (21s / 1min 31s)
.M
.[K[.[0;1;31m*.[0m.[0;31m*    .[0m] A stop job is running for /mnt/data (21s / 1min 31s)
.M
.[K[.[0m.[0;31m*     .[0m] A stop job is running for /mnt/data (22s / 1min 31s)
marmarek commented 4 years ago

Try After=qubes-qrexec-agent.service to the mount unit.

ardentbriar commented 4 years ago

Try After=qubes-qrexec-agent.service to the mount unit.

I just tried this. It still shows a delay.

[Unit]
Description=/mnt/data
BindsTo=data-server.socket
Wants=qubes-qrexec-agent.service
After=network.target
After=data-server.socket
After=qubes-qrexec-agent.service

[Mount]
What=localhost:/data
Where=/mnt/data
Type=nfs
Options=_netdev,auto

[Install]
WantedBy=multi-user.target
iamahuman commented 3 years ago

Related: #2826

github-actions[bot] commented 1 year ago

This issue is being closed because:

If anyone believes that this issue should be reopened and reassigned to an active milestone, please leave a brief comment. (For example, if a bug still affects Qubes OS 4.1, then the comment "Affects 4.1" will suffice.)