Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

'timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large' - may lead to connection and privacy issues #2044

Closed
adrelanos opened this issue Jun 3, 2016 · 5 comments
Closed

'timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large' - may lead to connection and privacy issues #2044

adrelanos opened this issue Jun 3, 2016 · 5 comments
Labels
C: templates P: major Priority: major. Between "default" and "critical" in severity. privacy This issue pertains to data or information privacy through technological means. T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists.

Comments

@adrelanos
Copy link
Member

Qubes OS version (e.g., R3.1):

R3.1

Affected TemplateVMs (e.g., fedora-23, if applicable):

debian-8, Fedora-23, Whonix 13, probably every template

Actual behavior:

qvm-run --pass-io sys-firewall date ; date

A two seconds time draft. (VM clock is two seconds faster.)

Does not always happen. If I spot this in one already running VM, I spot this in any already running VM that I test.

[271095.072610] timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large:
[271095.072619]         'xen' wd_now: f6aa707c0c8f wd_last: f6a8d4762faa mask: ffffffffffffffff
[271095.072624]         'tsc' cs_now: 1b6861d00 cs_last: 21d7172f2b8c4 mask: ffffffffffffffff

[user@sys-firewall ~]$ dmesg | grep clock
[    0.000000] clocksource refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.000000] clocksource xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.068803] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.149025] Switched to clocksource xen
[    1.160042] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x1fa3ddc950a, max_idle_ns: 440795245325 ns
[271095.072610] timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large:

[user@sys-firewall ~]$ dmesg | grep time
[    0.000000] Xen: using vcpuop timer interface
[    0.000000] installing Xen timer for CPU 0
[    0.001000] Calibrating delay loop (skipped), value calculated using timer frequency.. 4390.06 BogoMIPS (lpj=2195032)
[    0.001000] AppArmor: AppArmor disabled by boot time parameter
[    0.060351] installing Xen timer for CPU 1
[    0.061365] installing Xen timer for CPU 2
[    0.062398] installing Xen timer for CPU 3
[    0.063370] installing Xen timer for CPU 4
[    0.064337] installing Xen timer for CPU 5
[    0.065292] installing Xen timer for CPU 6
[    0.066241] installing Xen timer for CPU 7
[    0.089007] RTC time: 165:165:165, date: 165/165/65
[    1.797777] systemd-journald[174]: Received request to flush runtime journal from PID 1
[271095.072610] timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large:

Full dmesg attached below.

Expected behavior:

None of this should be happening.

Steps to reproduce the behavior:

No cause / effect witnessed yet. Please run dmesg | grep clock in your AppVMs every now and then (on various computers). If we are lucky you will be able to reproduce it yourself.

General notes:

Impact: Anonymity / Whonix is affected by this bug. Might break connectivity for some users. (#1779) On my systems, I witnessed only small skews yet, but for other users it may be much bigger and therefore causing Tor connection interruptions. Possibly also worsening privacy / fingerprinting.

Related issues:

#1779

[    0.000000] PAT configuration [0-7]: WB  WT  UC- UC  WC  WP  UC  UC  
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.1.13-9.pvops.qubes.x86_64 (user@release) (gcc version 4.8.3 20140911 (Red Hat 4.8.3-7) (GCC) ) #1 SMP Thu Feb 11 15:46:02 UTC 2016
[    0.000000] Command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH 3 nopat
[    0.000000] ACPI in unprivileged domain disabled
[    0.000000] Released 0 page(s)
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] Xen: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] Xen: [mem 0x00000000000a0000-0x00000000000fffff] reserved
[    0.000000] Xen: [mem 0x0000000000100000-0x00000000bb7fffff] usable
[    0.000000] PAT support disabled.
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: Xen
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0xbb800 max_arch_pfn = 0x400000000
[    0.000000] Base memory trampoline at [ffff88000009a000] 9a000 size 24576
[    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[    0.000000]  [mem 0x00000000-0x000fffff] page 4k
[    0.000000] init_memory_mapping: [mem 0x12a00000-0x12bfffff]
[    0.000000]  [mem 0x12a00000-0x12bfffff] page 4k
[    0.000000] BRK [0x0201f000, 0x0201ffff] PGTABLE
[    0.000000] init_memory_mapping: [mem 0x00100000-0x129fffff]
[    0.000000]  [mem 0x00100000-0x129fffff] page 4k
[    0.000000] init_memory_mapping: [mem 0x12c00000-0xbb7fffff]
[    0.000000]  [mem 0x12c00000-0xbb7fffff] page 4k
[    0.000000] BRK [0x02020000, 0x02020fff] PGTABLE
[    0.000000] BRK [0x02021000, 0x02021fff] PGTABLE
[    0.000000] BRK [0x02022000, 0x02022fff] PGTABLE
[    0.000000] BRK [0x02023000, 0x02023fff] PGTABLE
[    0.000000] BRK [0x02024000, 0x02024fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x02046000-0x027dcfff]
[    0.000000] NUMA turned off
[    0.000000] Faking a node at [mem 0x0000000000000000-0x00000000bb7fffff]
[    0.000000] NODE_DATA(0) allocated [mem 0x1262a000-0x1263dfff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x00000000bb7fffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x00000000bb7fffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x00000000bb7fffff]
[    0.000000] On node 0 totalpages: 767903
[    0.000000]   DMA zone: 64 pages used for memmap
[    0.000000]   DMA zone: 21 pages reserved
[    0.000000]   DMA zone: 3999 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 11936 pages used for memmap
[    0.000000]   DMA32 zone: 763904 pages, LIFO batch:31
[    0.000000] p2m virtual area at ffffc90000000000, size is 600000
[    0.000000] Remapped 0 page(s)
[    0.000000] SFI: Simple Firmware Interface v0.81 http://simplefirmware.org
[    0.000000] smpboot: Allowing 8 CPUs, 0 hotplug CPUs
[    0.000000] e820: [mem 0xbb800000-0xffffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on Xen
[    0.000000] Xen version: 4.6.0 (preserve-AD)
[    0.000000] clocksource refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.000000] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:8 nr_node_ids:1
[    0.000000] PERCPU: Embedded 34 pages/cpu @ffff88000ec00000 s101080 r8192 d29992 u262144
[    0.000000] pcpu-alloc: s101080 r8192 d29992 u262144 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 1 2 3 4 5 6 7 
[    0.000000] xen: PV spinlocks enabled
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 755882
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH 3 nopat
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] xsave: enabled xstate_bv 0x7, cntxt size 0x340 using standard form
[    0.000000] Memory: 219700K/3071612K available (7578K kernel code, 1219K rwdata, 3272K rodata, 1504K init, 1464K bss, 2851912K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000]  RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=8.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=8
[    0.000000] NR_IRQS:4352 nr_irqs:144 16
[    0.000000] xen:events: Using FIFO-based ABI
[    0.000000]  Offload RCU callbacks from all CPUs
[    0.000000]  Offload RCU callbacks from CPUs: 0-7.
[    0.000000] Console: colour dummy device 80x25
[    0.000000] console [tty0] enabled
[    0.000000] console [hvc0] enabled
[    0.000000] clocksource xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] Xen: using vcpuop timer interface
[    0.000000] installing Xen timer for CPU 0
[    0.000000] tsc: Detected 2195.032 MHz processor
[    0.001000] Calibrating delay loop (skipped), value calculated using timer frequency.. 4390.06 BogoMIPS (lpj=2195032)
[    0.001000] pid_max: default: 32768 minimum: 301
[    0.001000] Security Framework initialized
[    0.001000] AppArmor: AppArmor disabled by boot time parameter
[    0.001000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.001423] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.001679] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.001693] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.001888] Initializing cgroup subsys blkio
[    0.001895] Initializing cgroup subsys memory
[    0.001907] Initializing cgroup subsys devices
[    0.001913] Initializing cgroup subsys freezer
[    0.001918] Initializing cgroup subsys net_cls
[    0.001924] Initializing cgroup subsys perf_event
[    0.001930] Initializing cgroup subsys net_prio
[    0.001936] Initializing cgroup subsys hugetlb
[    0.001985] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.001989] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
[    0.001995] CPU: Physical Processor ID: 0
[    0.001999] CPU: Processor Core ID: 1
[    0.002798] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[    0.002802] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[    0.027351] ftrace: allocating 27794 entries in 109 pages
[    0.032050] cpu 0 spinlock event irq 17
[    0.039131] Performance Events: unsupported p6 CPU model 70 no PMU driver, software events only.
[    0.039645] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.039649] NMI watchdog: Shutting down hard lockup detector on all cpus
[    0.039705] SMP alternatives: switching to SMP code
[    0.060351] installing Xen timer for CPU 1
[    0.060366] cpu 1 spinlock event irq 24
[    0.061365] installing Xen timer for CPU 2
[    0.061374] cpu 2 spinlock event irq 31
[    0.062398] installing Xen timer for CPU 3
[    0.062404] cpu 3 spinlock event irq 38
[    0.063370] installing Xen timer for CPU 4
[    0.063377] cpu 4 spinlock event irq 45
[    0.064337] installing Xen timer for CPU 5
[    0.064344] cpu 5 spinlock event irq 52
[    0.065292] installing Xen timer for CPU 6
[    0.065299] cpu 6 spinlock event irq 59
[    0.066241] installing Xen timer for CPU 7
[    0.066248] cpu 7 spinlock event irq 66
[    0.067135] x86: Booted up 1 node, 8 CPUs
[    0.067193] devtmpfs: initialized
[    0.068803] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.069012] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    0.069018] pinctrl core: initialized pinctrl subsystem
[    0.089007] RTC time: 165:165:165, date: 165/165/65
[    0.089127] NET: Registered protocol family 16
[    0.089149] xen:grant_table: Grant tables using version 1 layout
[    0.089157] Grant table initialized
[    0.089379] PCI: setting up Xen PCI frontend stub
[    0.089385] PCI: pci_cache_line_size set to 64 bytes
[    0.093079] ACPI: Interpreter disabled.
[    0.093079] xen:balloon: Initialising balloon driver
[    0.100018] xen_balloon: Initialising balloon driver
[    0.100037] vgaarb: loaded
[    0.100057] SCSI subsystem initialized
[    0.100083] libata version 3.00 loaded.
[    0.100083] usbcore: registered new interface driver usbfs
[    0.100083] usbcore: registered new interface driver hub
[    0.100083] usbcore: registered new device driver usb
[    0.100128] PCI: System does not support PCI
[    0.100128] PCI: System does not support PCI
[    0.100128] NetLabel: Initializing
[    0.100128] NetLabel:  domain hash size = 128
[    0.100128] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.100128] NetLabel:  unlabeled traffic allowed by default
[    0.149025] Switched to clocksource xen
[    0.153214] pnp: PnP ACPI: disabled
[    0.154680] NET: Registered protocol family 2
[    0.154834] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.154930] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    0.154976] TCP: Hash tables configured (established 32768 bind 32768)
[    0.154995] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    0.155019] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    0.155058] NET: Registered protocol family 1
[    0.155071] PCI: CLS 0 bytes, default 64
[    0.155105] Unpacking initramfs...
[    0.160131] Freeing initrd memory: 7772K (ffff880002046000 - ffff8800027dd000)
[    0.160227] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    0.160796] AVX2 version of gcm_enc/dec engaged.
[    0.160800] AES CTR mode by8 optimization enabled
[    0.162047] alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
[    0.162367] futex hash table entries: 2048 (order: 5, 131072 bytes)
[    0.162387] Initialise system trusted keyring
[    0.162404] audit: initializing netlink subsys (disabled)
[    0.162414] audit: type=2000 audit(1464686860.700:1): initialized
[    0.162607] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.163535] zpool: loaded
[    0.163540] zbud: loaded
[    0.163663] VFS: Disk quotas dquot_6.6.0
[    0.163687] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.163961] Key type big_key registered
[    0.164420] alg: No test for stdrng (krng)
[    0.164430] NET: Registered protocol family 38
[    0.164439] Key type asymmetric registered
[    0.164443] Asymmetric key parser 'x509' registered
[    0.164469] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    0.164531] io scheduler noop registered
[    0.164535] io scheduler deadline registered
[    0.164561] io scheduler cfq registered (default)
[    0.164617] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.164629] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.164650] intel_idle: does not run on family 6 model 70
[    0.164786] xen:xen_evtchn: Event-channel device installed
[    0.165091] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.165394] Non-volatile memory driver v1.3
[    0.165424] Linux agpgart interface v0.103
[    0.165975] libphy: Fixed MDIO Bus: probed
[    0.166036] usbcore: registered new interface driver usbserial
[    0.166044] usbcore: registered new interface driver usbserial_generic
[    0.166052] usbserial: USB Serial support registered for generic
[    0.166067] i8042: PNP: No PS/2 controller found. Probing ports directly.
[    1.160042] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x1fa3ddc950a, max_idle_ns: 440795245325 ns
[    1.176408] i8042: No controller found
[    1.176511] mousedev: PS/2 mouse device common for all mice
[    1.196638] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[    1.196709] rtc_cmos: probe of rtc_cmos failed with error -38
[    1.196778] device-mapper: uevent: version 1.0.3
[    1.196854] device-mapper: ioctl: 4.31.0-ioctl (2015-3-12) initialised: [email protected]
[    1.196941] hidraw: raw HID events driver (C) Jiri Kosina
[    1.196977] usbcore: registered new interface driver usbhid
[    1.196981] usbhid: USB HID core driver
[    1.197019] drop_monitor: Initializing network drop monitor service
[    1.197078] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.197314] Initializing XFRM netlink socket
[    1.197388] NET: Registered protocol family 10
[    1.197588] mip6: Mobile IPv6
[    1.197596] NET: Registered protocol family 17
[    1.197605] mce: Unable to init device /dev/mcelog (rc: -5)
[    1.197781] Loading compiled-in X.509 certificates
[    1.197795] registered taskstats version 1
[    1.197858] xenbus_probe_frontend: Device with no driver: device/vbd/51712
[    1.197864] xenbus_probe_frontend: Device with no driver: device/vbd/51728
[    1.197868] xenbus_probe_frontend: Device with no driver: device/vbd/51744
[    1.197873] xenbus_probe_frontend: Device with no driver: device/vbd/51760
[    1.197877] xenbus_probe_frontend: Device with no driver: device/vif/0
[    1.197937]   Magic number: 1:252:3141
[    1.197960] hctosys: unable to open rtc device (rtc0)
[    1.198409] Freeing unused kernel memory: 1504K (ffffffff81d32000 - ffffffff81eaa000)
[    1.198415] Write protecting the kernel read-only data: 12288k
[    1.200693] Freeing unused kernel memory: 604K (ffff880001769000 - ffff880001800000)
[    1.200937] Freeing unused kernel memory: 824K (ffff880001b32000 - ffff880001c00000)
[    1.203962] random: modprobe urandom read with 38 bits of entropy available
[    1.216108] blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.229243] blkfront: xvdb: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.235364] blkfront: xvdc: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.239219] blkfront: xvdd: barrier or flush: disabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.334371]  xvdc: xvdc1 xvdc2
[    1.367029] EXT4-fs (dm-0): couldn't mount as ext3 due to feature incompatibilities
[    1.367121] EXT4-fs (dm-0): couldn't mount as ext2 due to feature incompatibilities
[    1.367762] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[    1.370004] EXT4-fs (xvdd): mounting ext3 file system using the ext4 subsystem
[    1.370425] EXT4-fs (xvdd): mounted filesystem with ordered data mode. Opts: (null)
[    1.409008] random: nonblocking pool is initialized
[    1.423375] systemd[1]: systemd 222 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    1.423423] systemd[1]: Detected virtualization xen.
[    1.423433] systemd[1]: Detected architecture x86-64.
[    1.423841] systemd[1]: No hostname configured.
[    1.423851] systemd[1]: Set hostname to <localhost>.
[    1.464233] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    1.464253] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[    1.464344] systemd[1]: Reached target Remote File Systems.
[    1.464354] systemd[1]: Starting Remote File Systems.
[    1.464593] systemd[1]: Created slice Root Slice.
[    1.464602] systemd[1]: Starting Root Slice.
[    1.464711] systemd[1]: Listening on Journal Audit Socket.
[    1.464720] systemd[1]: Starting Journal Audit Socket.
[    1.464785] systemd[1]: Listening on udev Control Socket.
[    1.464794] systemd[1]: Starting udev Control Socket.
[    1.464856] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    1.464864] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[    1.464925] systemd[1]: Listening on Journal Socket (/dev/log).
[    1.464933] systemd[1]: Starting Journal Socket (/dev/log).
[    1.464987] systemd[1]: Listening on udev Kernel Socket.
[    1.464995] systemd[1]: Starting udev Kernel Socket.
[    1.465072] systemd[1]: Listening on Journal Socket.
[    1.465085] systemd[1]: Starting Journal Socket.
[    1.465211] systemd[1]: Created slice User and Session Slice.
[    1.465220] systemd[1]: Starting User and Session Slice.
[    1.465338] systemd[1]: Created slice System Slice.
[    1.465351] systemd[1]: Starting System Slice.
[    1.466141] systemd[1]: Starting Journal Service...
[    1.466322] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    1.466339] systemd[1]: Starting system-serial\x2dgetty.slice.
[    1.561456] systemd[1]: Mounting Huge Pages File System...
[    1.562708] systemd[1]: Mounting Debug File System...
[    1.562870] systemd[1]: Reached target Slices.
[    1.562896] systemd[1]: Starting Slices.
[    1.564379] systemd[1]: Starting Load Kernel Modules...
[    1.564664] systemd[1]: Created slice system-getty.slice.
[    1.564693] systemd[1]: Starting system-getty.slice.
[    1.565776] systemd[1]: Starting Load legacy module configuration...
[    1.567146] systemd[1]: Starting Setup Virtual Console...
[    1.568162] systemd[1]: Mounting POSIX Message Queue File System...
[    1.569729] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    1.569948] systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway.
[    1.571185] systemd[1]: Mounting Temporary Directory...
[    1.571578] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    1.571619] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
[    1.571870] systemd[1]: Started Set Up Additional Binary Formats.
[    1.573227] systemd[1]: Starting File System Check on Root Device...
[    1.574577] systemd[1]: Mounting /proc/xen...
[    1.574756] systemd[1]: Reached target Encrypted Volumes.
[    1.574796] systemd[1]: Starting Encrypted Volumes.
[    1.576325] systemd[1]: Mounted POSIX Message Queue File System.
[    1.576403] systemd[1]: Mounted Huge Pages File System.
[    1.576477] systemd[1]: Mounted Debug File System.
[    1.576541] systemd[1]: Mounted Temporary Directory.
[    1.576780] systemd[1]: Started Journal Service.
[    1.576933] audit: type=1130 audit(1464686862.114: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'
[    1.577058] dummy_hcd dummy_hcd.0: USB Host+Gadget Emulator, driver 02 May 2005
[    1.577071] dummy_hcd dummy_hcd.0: Dummy host controller
[    1.577153] dummy_hcd dummy_hcd.0: new USB bus registered, assigned bus number 1
[    1.577201] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.577208] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.577216] usb usb1: Product: Dummy host controller
[    1.577223] usb usb1: Manufacturer: Linux 4.1.13-9.pvops.qubes.x86_64 dummy_hcd
[    1.577229] usb usb1: SerialNumber: dummy_hcd.0
[    1.577378] hub 1-0:1.0: USB hub found
[    1.577390] hub 1-0:1.0: 1 port detected
[    1.760971] audit: type=1130 audit(1464686862.298:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=fedora-loadmodules comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.761407] audit: type=1130 audit(1464686862.299:4): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.761926] audit: type=1130 audit(1464686862.299:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-modules-load comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.762309] audit: type=1130 audit(1464686862.300:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=kmod-static-nodes comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.778778] audit: type=1130 audit(1464686862.316:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.781481] audit: type=1130 audit(1464686862.319:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.786044] EXT4-fs (dm-0): re-mounted. Opts: (null)
[    1.789829] audit: type=1130 audit(1464686862.327:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-remount-fs comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.797777] systemd-journald[174]: Received request to flush runtime journal from PID 1
[    1.801683] audit: type=1130 audit(1464686862.339:10): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.849964] input: PC Speaker as /devices/platform/pcspkr/input/input0
[    1.868373] xen_netfront: Initialising Xen virtual ethernet driver
[    1.961446] alg: No test for crc32 (crc32-pclmul)
[    2.031553] nf_conntrack version 0.5.0 (1800 buckets, 7200 max)
[    4.742400] Adding 1048572k swap on /dev/xvdc1.  Priority:-1 extents:1 across:1048572k SSFS
[    5.052849] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    5.080762] EXT4-fs (xvdb): mounted filesystem with ordered data mode. Opts: discard
[    6.233084] IPv6: ADDRCONF(NETDEV_UP): vif3.0: link is not ready
[    8.225068] vif vif-3-0 vif3.0: Guest Rx ready
[    8.225102] IPv6: ADDRCONF(NETDEV_CHANGE): vif3.0: link becomes ready
[   24.108738] fuse init (API version 7.23)
[  157.464424] IPv6: ADDRCONF(NETDEV_UP): vif4.0: link is not ready
[  159.660716] vif vif-4-0 vif4.0: Guest Rx ready
[  159.660741] IPv6: ADDRCONF(NETDEV_CHANGE): vif4.0: link becomes ready
[  160.787419] IPv6: ADDRCONF(NETDEV_UP): vif5.0: link is not ready
[  162.878026] vif vif-5-0 vif5.0: Guest Rx ready
[  162.878078] IPv6: ADDRCONF(NETDEV_CHANGE): vif5.0: link becomes ready
[  164.996558] IPv6: ADDRCONF(NETDEV_UP): vif6.0: link is not ready
[  167.380294] vif vif-6-0 vif6.0: Guest Rx ready
[  167.380314] IPv6: ADDRCONF(NETDEV_CHANGE): vif6.0: link becomes ready
[  411.620162] IPv6: ADDRCONF(NETDEV_UP): vif8.0: link is not ready
[  413.701255] vif vif-8-0 vif8.0: Guest Rx ready
[  413.701285] IPv6: ADDRCONF(NETDEV_CHANGE): vif8.0: link becomes ready
[ 4020.216591] IPv6: ADDRCONF(NETDEV_UP): vif9.0: link is not ready
[ 4022.336079] vif vif-9-0 vif9.0: Guest Rx ready
[ 4022.336099] IPv6: ADDRCONF(NETDEV_CHANGE): vif9.0: link becomes ready
[26299.580600] IPv6: ADDRCONF(NETDEV_UP): vif11.0: link is not ready
[26302.059399] vif vif-11-0 vif11.0: Guest Rx ready
[26302.059420] IPv6: ADDRCONF(NETDEV_CHANGE): vif11.0: link becomes ready
[271095.072610] timekeeping watchdog: Marking clocksource 'tsc' as unstable, because the skew is too large:
[271095.072619]     'xen' wd_now: f6aa707c0c8f wd_last: f6a8d4762faa mask: ffffffffffffffff
[271095.072624]     'tsc' cs_now: 1b6861d00 cs_last: 21d7172f2b8c4 mask: ffffffffffffffff
[272910.669973] IPv6: ADDRCONF(NETDEV_UP): vif16.0: link is not ready
[272913.183980] vif vif-16-0 vif16.0: Guest Rx ready
[272913.183998] IPv6: ADDRCONF(NETDEV_CHANGE): vif16.0: link becomes ready
[285388.035112] IPv6: ADDRCONF(NETDEV_UP): vif17.0: link is not ready
[285390.265269] vif vif-17-0 vif17.0: Guest Rx ready
[285390.265291] IPv6: ADDRCONF(NETDEV_CHANGE): vif17.0: link becomes ready
@adrelanos adrelanos mentioned this issue Jun 3, 2016
Closed
@andrewdavidwong andrewdavidwong added T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists. C: templates P: major Priority: major. Between "default" and "critical" in severity. privacy This issue pertains to data or information privacy through technological means. labels Jun 3, 2016
@marmarek
Copy link
Member

marmarek commented Jun 4, 2016

Does it happen after system suspend? That may cause Marking clocksource 'tsc' as unstable message.
As for the clock skew, clock synchronization mechanism in Qubes is quite inaccurate. First of all, it has 1 second precision. But then it is performed by:

  1. Call date -u -Iseconds in dom0.
  2. Pass the output to qubes.SetDateTime RPC service.
    There may be arbitrary large time between those two, depending mostly on system load. In most cases it should be in order of milliseconds. Shouldn't be a problem for any connectivity.

But how that would lead to privacy problems? AFAIR you've told that slightly different time in VMs is actually a good thing for privacy. In addition to Whonix using its own time synchronization mechanism, it should actually improve privacy (sys-net and others have slightly different time than dom0, so even if dom0 time is leaked, it's hard to link it with any timestamp leaked through clearnet connections).

@adrelanos
Copy link
Member Author

Marek Marczykowski-Górecki:

Does it happen after system suspend?

No system suspend involved. (I personally use this almost never except
for testing.)

AFAIR you've told that slightly different time in VMs is actually a good thing for privacy.

In addition to Whonix using its own time synchronization mechanism, it should actually improve privacy

Yes, but 1) and 2) both require a functional VM clock to begin with. If
it jumps arbitrarily due to xen / linux kernel issues, then it cannot work.

But how that would lead to privacy problems?

sdwdate has a certain range of accuracy. While I am experiencing only
small skews, I was reporting this bug, because I guess it could also
lead to huge jumps as described in #1779. Such jumps would be outside
the usual accuracy of sdwdate, hence stand out from others. And such big
jumps can also disrupt connectivity (Tor needs a reasonable correct
clock otherwise it fails to operate...) as described in #1779.

@marmarek
Copy link
Member

marmarek commented Jun 5, 2016

Yes, but 1) and 2) both require a functional VM clock to begin with. If it jumps arbitrarily due to xen / linux kernel issues, then it cannot work.

The message you've included shouldn't result in huge clock jumps. Pausing a VM (including system suspend) without synchronizing the clock afterwards will. But it is unrelated situation.

@adrelanos
Copy link
Member Author

adrelanos commented Jun 5, 2016 via email

@andrewdavidwong andrewdavidwong added this to the Far in the future milestone Dec 24, 2016
@adrelanos adrelanos mentioned this issue Jun 3, 2017
Closed
@andrewdavidwong
Copy link
Member

This bug report has seen no activity in a very long time, and it is not assigned to any current release milestone. It looks like it was left open by mistake, so I'm closing it now. However, if anyone is still affected by this bug on a currently-supported release, please leave a comment, and we'll be happy to reopen this. Thank you.

@brendanhoar brendanhoar mentioned this issue Apr 29, 2022
Open
marmarek added a commit to marmarek/qubes-core-admin that referenced this issue May 3, 2022
@marmarek
Properly suspend all VMs, not only those with PCI devices
e7e4e36 
Just pausing a VM for a host suspend breaks 'tsc' clocksource.

QubesOS/qubes-issues#7404
QubesOS/qubes-issues#2044
@marmarek marmarek mentioned this issue May 3, 2022
Merged
4 tasks
marmarek added a commit to marmarek/qubes-core-agent-linux that referenced this issue Jun 6, 2022
@marmarek
prepare-suspend: do not disable virtual interfaces before suspend
ce8bfa0 
There is no need to disable virtual (dummy) interfaces before suspend,
it matters only for physical ones. Especially, do not de-configure dummy
eth1 used by Whonix, as there is nothing to turn it back on after
resume.

QubesOS/qubes-issues#2044
QubesOS/qubes-issues#7404
@marmarek marmarek mentioned this issue Jun 6, 2022
Merged
@qubesos-bot qubesos-bot mentioned this issue Oct 26, 2022
Closed
marmarek added a commit to QubesOS/qubes-core-agent-linux that referenced this issue Nov 29, 2022
@marmarek
prepare-suspend: do not disable virtual interfaces before suspend
9bed013 
There is no need to disable virtual (dummy) interfaces before suspend,
it matters only for physical ones. Especially, do not de-configure dummy
eth1 used by Whonix, as there is nothing to turn it back on after
resume.

QubesOS/qubes-issues#2044
QubesOS/qubes-issues#7404

(cherry picked from commit ce8bfa0)
@qubesos-bot qubesos-bot mentioned this issue Nov 29, 2022
Closed
@qubesos-bot qubesos-bot mentioned this issue Jan 1, 2023
Closed
@andrewdavidwong andrewdavidwong removed this from the Release TBD milestone Jul 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C: templates P: major Priority: major. Between "default" and "critical" in severity. privacy This issue pertains to data or information privacy through technological means. T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@marmarek @adrelanos @andrewdavidwong