jkryl
commented
3 years ago Closed jkryl closed 2 years ago
jkryl
commented
3 years ago 
gila
commented
3 years ago We are missing kernel logs, can we add them? It might be the in-capsule bug in older 5.x kernels where in effect the connection to the target is lost and the kernel will hang. Could we add them? @jkryl
ghost
commented
3 years ago ubuntu@ip-172-20-52-180:~$ sudo dmesg
[ 0.000000] Linux version 5.9.1-050901-generic (kernel@kathleen) (gcc (Ubuntu 10.2.0-13ubuntu1) 10.2.0, GNU ld (GNU Binutils for Ubuntu) 2.35.1) #202010170731 SMP Sat Oct 17 07:42:59 UTC 2020
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.9.1-050901-generic root=PARTUUID=093eb684-01 ro console=tty1 console=ttyS0 nvme_core.io_timeout=4294967295
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Hygon HygonGenuine
[ 0.000000] Centaur CentaurHauls
[ 0.000000] zhaoxin Shanghai
[ 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: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bfff9fff] usable
[ 0.000000] BIOS-e820: [mem 0x00000000bfffa000-0x00000000bfffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000e03fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000022fffffff] usable
[ 0.000000] BIOS-e820: [mem 0x0000000230000000-0x000000023fffffff] reserved
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.7 present.
[ 0.000000] DMI: Amazon EC2 m5ad.large/, BIOS 1.0 10/16/2017
[ 0.000000] Hypervisor detected: KVM
[ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[ 0.000000] kvm-clock: cpu 0, msr 6601001, primary cpu clock
[ 0.000000] kvm-clock: using sched offset of 22242622130 cycles
[ 0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[ 0.000005] tsc: Detected 2199.850 MHz processor
[ 0.000698] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.000700] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.000704] last_pfn = 0x230000 max_arch_pfn = 0x400000000
[ 0.000753] MTRR default type: write-back
[ 0.000754] MTRR fixed ranges enabled:
[ 0.000755] 00000-9FFFF write-back
[ 0.000756] A0000-BFFFF uncachable
[ 0.000757] C0000-FFFFF write-protect
[ 0.000758] MTRR variable ranges enabled:
[ 0.000759] 0 base 0000C0000000 mask FFFFC0000000 uncachable
[ 0.000760] 1 disabled
[ 0.000761] 2 disabled
[ 0.000761] 3 disabled
[ 0.000761] 4 disabled
[ 0.000762] 5 disabled
[ 0.000762] 6 disabled
[ 0.000763] 7 disabled
[ 0.000779] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
[ 0.000791] last_pfn = 0xbfffa max_arch_pfn = 0x400000000
[ 0.006483] check: Scanning 1 areas for low memory corruption
[ 0.006516] Using GB pages for direct mapping
[ 0.006849] RAMDISK: [mem 0x2e15f000-0x330a6fff]
[ 0.006874] ACPI: Early table checksum verification disabled
[ 0.006878] ACPI: RSDP 0x00000000000F8F90 000014 (v00 AMAZON)
[ 0.006886] ACPI: RSDT 0x00000000BFFFE360 00003C (v01 AMAZON AMZNRSDT 00000001 AMZN 00000001)
[ 0.006892] ACPI: FACP 0x00000000BFFFFF80 000074 (v01 AMAZON AMZNFACP 00000001 AMZN 00000001)
[ 0.006898] ACPI: DSDT 0x00000000BFFFE3A0 0010E9 (v01 AMAZON AMZNDSDT 00000001 AMZN 00000001)
[ 0.006902] ACPI: FACS 0x00000000BFFFFF40 000040
[ 0.006905] ACPI: SSDT 0x00000000BFFFF6C0 00087A (v01 AMAZON AMZNSSDT 00000001 AMZN 00000001)
[ 0.006908] ACPI: APIC 0x00000000BFFFF5D0 000076 (v01 AMAZON AMZNAPIC 00000001 AMZN 00000001)
[ 0.006912] ACPI: SRAT 0x00000000BFFFF530 0000A0 (v01 AMAZON AMZNSRAT 00000001 AMZN 00000001)
[ 0.006915] ACPI: SLIT 0x00000000BFFFF4C0 00006C (v01 AMAZON AMZNSLIT 00000001 AMZN 00000001)
[ 0.006918] ACPI: WAET 0x00000000BFFFF490 000028 (v01 AMAZON AMZNWAET 00000001 AMZN 00000001)
[ 0.006926] ACPI: Local APIC address 0xfee00000
[ 0.006950] SRAT: PXM 0 -> APIC 0x00 -> Node 0
[ 0.006951] SRAT: PXM 0 -> APIC 0x01 -> Node 0
[ 0.006954] ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0xbfffffff]
[ 0.006956] ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0x23fffffff]
[ 0.006962] NUMA: Initialized distance table, cnt=1
[ 0.006964] NUMA: Node 0 [mem 0x00000000-0xbfffffff] + [mem 0x100000000-0x22fffffff] -> [mem 0x00000000-0x22fffffff]
[ 0.006974] NODE_DATA(0) allocated [mem 0x22ffd3000-0x22fffcfff]
[ 0.007343] Zone ranges:
[ 0.007344] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.007346] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
[ 0.007347] Normal [mem 0x0000000100000000-0x000000022fffffff]
[ 0.007348] Device empty
[ 0.007349] Movable zone start for each node
[ 0.007353] Early memory node ranges
[ 0.007354] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.007356] node 0: [mem 0x0000000000100000-0x00000000bfff9fff]
[ 0.007357] node 0: [mem 0x0000000100000000-0x000000022fffffff]
[ 0.007371] Zeroed struct page in unavailable ranges: 104 pages
[ 0.007372] Initmem setup node 0 [mem 0x0000000000001000-0x000000022fffffff]
[ 0.007374] On node 0 totalpages: 2031512
[ 0.007375] DMA zone: 64 pages used for memmap
[ 0.007376] DMA zone: 21 pages reserved
[ 0.007377] DMA zone: 3998 pages, LIFO batch:0
[ 0.007402] DMA32 zone: 12224 pages used for memmap
[ 0.007403] DMA32 zone: 782330 pages, LIFO batch:63
[ 0.012895] Normal zone: 19456 pages used for memmap
[ 0.012897] Normal zone: 1245184 pages, LIFO batch:63
[ 0.022335] ACPI: PM-Timer IO Port: 0xb008
[ 0.022339] ACPI: Local APIC address 0xfee00000
[ 0.022346] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[ 0.022378] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[ 0.022381] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[ 0.022383] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.022385] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[ 0.022386] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[ 0.022387] ACPI: IRQ5 used by override.
[ 0.022388] ACPI: IRQ9 used by override.
[ 0.022389] ACPI: IRQ10 used by override.
[ 0.022389] ACPI: IRQ11 used by override.
[ 0.022391] Using ACPI (MADT) for SMP configuration information
[ 0.022397] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[ 0.022423] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[ 0.022425] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.022426] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
[ 0.022427] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[ 0.022429] PM: hibernation: Registered nosave memory: [mem 0xbfffa000-0xbfffffff]
[ 0.022430] PM: hibernation: Registered nosave memory: [mem 0xc0000000-0xdfffffff]
[ 0.022431] PM: hibernation: Registered nosave memory: [mem 0xe0000000-0xe03fffff]
[ 0.022432] PM: hibernation: Registered nosave memory: [mem 0xe0400000-0xfffbffff]
[ 0.022433] PM: hibernation: Registered nosave memory: [mem 0xfffc0000-0xffffffff]
[ 0.022435] [mem 0xc0000000-0xdfffffff] available for PCI devices
[ 0.022436] Booting paravirtualized kernel on KVM
[ 0.022439] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[ 0.022451] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:2 nr_cpu_ids:2 nr_node_ids:1
[ 0.022707] percpu: Embedded 56 pages/cpu s192512 r8192 d28672 u1048576
[ 0.022713] pcpu-alloc: s192512 r8192 d28672 u1048576 alloc=1*2097152
[ 0.022713] pcpu-alloc: [0] 0 1
[ 0.022740] kvm-guest: stealtime: cpu 0, msr 22802e080
[ 0.022743] kvm-guest: PV spinlocks disabled, no host support
[ 0.022748] Built 1 zonelists, mobility grouping on. Total pages: 1999747
[ 0.022749] Policy zone: Normal
[ 0.022751] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.9.1-050901-generic root=PARTUUID=093eb684-01 ro console=tty1 console=ttyS0 nvme_core.io_timeout=4294967295
[ 0.023656] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
[ 0.024055] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[ 0.024086] mem auto-init: stack:off, heap alloc:on, heap free:off
[ 0.045703] Memory: 7801740K/8126048K available (14339K kernel code, 2592K rwdata, 8696K rodata, 2640K init, 4860K bss, 324048K reserved, 0K cma-reserved)
[ 0.045710] random: get_random_u64 called from kmem_cache_open+0x29/0x220 with crng_init=0
[ 0.045828] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[ 0.045842] ftrace: allocating 49194 entries in 193 pages
[ 0.064317] ftrace: allocated 193 pages with 3 groups
[ 0.064423] rcu: Hierarchical RCU implementation.
[ 0.064425] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=2.
[ 0.064426] Trampoline variant of Tasks RCU enabled.
[ 0.064426] Rude variant of Tasks RCU enabled.
[ 0.064427] Tracing variant of Tasks RCU enabled.
[ 0.064428] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[ 0.064429] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[ 0.067720] NR_IRQS: 524544, nr_irqs: 440, preallocated irqs: 16
[ 0.067989] random: crng done (trusting CPU's manufacturer)
[ 0.187367] Console: colour VGA+ 80x25
[ 0.533024] printk: console [tty1] enabled
[ 0.715464] printk: console [ttyS0] enabled
[ 0.719043] ACPI: Core revision 20200717
[ 0.722579] APIC: Switch to symmetric I/O mode setup
[ 0.727802] ..TIMER: vector=0x30 apic1=0 pin1=0 apic2=-1 pin2=-1
[ 0.732217] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1fb5a559600, max_idle_ns: 440795315627 ns
[ 0.740048] Calibrating delay loop (skipped) preset value.. 4399.70 BogoMIPS (lpj=8799400)
[ 0.744047] pid_max: default: 32768 minimum: 301
[ 0.748077] LSM: Security Framework initializing
[ 0.751800] Yama: becoming mindful.
[ 0.752073] AppArmor: AppArmor initialized
[ 0.756097] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 0.760057] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 0.768597] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 512
[ 0.772049] Last level dTLB entries: 4KB 1536, 2MB 1536, 4MB 768, 1GB 0
[ 0.776049] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[ 0.780048] Spectre V2 : Mitigation: Full AMD retpoline
[ 0.784047] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 0.788047] Speculative Store Bypass: Vulnerable
[ 0.792319] Freeing SMP alternatives memory: 40K
[ 0.909696] smpboot: CPU0: AMD EPYC 7571 (family: 0x17, model: 0x1, stepping: 0x2)
[ 0.912181] Performance Events: PMU not available due to virtualization, using software events only.
[ 0.916080] rcu: Hierarchical SRCU implementation.
[ 0.920206] NMI watchdog: Perf NMI watchdog permanently disabled
[ 0.924089] smp: Bringing up secondary CPUs ...
[ 0.928173] x86: Booting SMP configuration:
[ 0.932050] .... node #0, CPUs: #1
[ 0.664140] kvm-clock: cpu 1, msr 6601041, secondary cpu clock
[ 0.936066] kvm-guest: stealtime: cpu 1, msr 22812e080
[ 0.944135] smp: Brought up 1 node, 2 CPUs
[ 0.948047] smpboot: Max logical packages: 1
[ 0.952048] smpboot: Total of 2 processors activated (8799.40 BogoMIPS)
[ 0.956673] devtmpfs: initialized
[ 0.960097] x86/mm: Memory block size: 128MB
[ 0.964574] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[ 0.968054] futex hash table entries: 512 (order: 3, 32768 bytes, linear)
[ 0.972119] pinctrl core: initialized pinctrl subsystem
[ 0.976303] PM: RTC time: 12:54:16, date: 2020-10-21
[ 0.980234] NET: Registered protocol family 16
[ 0.984207] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[ 0.988878] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[ 0.992122] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[ 0.996054] audit: initializing netlink subsys (disabled)
[ 1.000071] audit: type=2000 audit(1603284855.092:1): state=initialized audit_enabled=0 res=1
[ 1.000227] thermal_sys: Registered thermal governor 'fair_share'
[ 1.000228] thermal_sys: Registered thermal governor 'bang_bang'
[ 1.008048] thermal_sys: Registered thermal governor 'step_wise'
[ 1.052048] thermal_sys: Registered thermal governor 'user_space'
[ 1.056047] thermal_sys: Registered thermal governor 'power_allocator'
[ 1.060055] EISA bus registered
[ 1.068073] cpuidle: using governor ladder
[ 1.072053] cpuidle: using governor menu
[ 1.076908] ACPI: bus type PCI registered
[ 1.080048] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 1.084202] PCI: Using configuration type 1 for base access
[ 1.088047] PCI: Using configuration type 1 for extended access
[ 1.096894] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[ 1.100049] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 1.108193] ACPI: Added _OSI(Module Device)
[ 1.112055] ACPI: Added _OSI(Processor Device)
[ 1.116047] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 1.120047] ACPI: Added _OSI(Processor Aggregator Device)
[ 1.124048] ACPI: Added _OSI(Linux-Dell-Video)
[ 1.128048] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[ 1.132048] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[ 1.138089] ACPI: 2 ACPI AML tables successfully acquired and loaded
[ 1.144410] ACPI: Interpreter enabled
[ 1.147702] ACPI: (supports S0 S4 S5)
[ 1.148048] ACPI: Using IOAPIC for interrupt routing
[ 1.152066] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 1.156487] ACPI: Enabled 16 GPEs in block 00 to 0F
[ 1.165972] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 1.168056] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[ 1.172546] acpiphp: Slot [3] registered
[ 1.176083] acpiphp: Slot [4] registered
[ 1.180074] acpiphp: Slot [5] registered
[ 1.184074] acpiphp: Slot [6] registered
[ 1.187537] acpiphp: Slot [7] registered
[ 1.188075] acpiphp: Slot [8] registered
[ 1.192076] acpiphp: Slot [9] registered
[ 1.196073] acpiphp: Slot [10] registered
[ 1.200074] acpiphp: Slot [11] registered
[ 1.204071] acpiphp: Slot [12] registered
[ 1.208075] acpiphp: Slot [13] registered
[ 1.212075] acpiphp: Slot [14] registered
[ 1.216081] acpiphp: Slot [15] registered
[ 1.220095] acpiphp: Slot [16] registered
[ 1.223636] acpiphp: Slot [17] registered
[ 1.224105] acpiphp: Slot [18] registered
[ 1.228075] acpiphp: Slot [19] registered
[ 1.232075] acpiphp: Slot [20] registered
[ 1.236077] acpiphp: Slot [21] registered
[ 1.240074] acpiphp: Slot [22] registered
[ 1.244071] acpiphp: Slot [23] registered
[ 1.248074] acpiphp: Slot [24] registered
[ 1.252074] acpiphp: Slot [25] registered
[ 1.256074] acpiphp: Slot [26] registered
[ 1.260075] acpiphp: Slot [27] registered
[ 1.264076] acpiphp: Slot [28] registered
[ 1.267733] acpiphp: Slot [29] registered
[ 1.268076] acpiphp: Slot [30] registered
[ 1.272077] acpiphp: Slot [31] registered
[ 1.276067] PCI host bridge to bus 0000:00
[ 1.280050] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 1.284048] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 1.288049] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 1.292048] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
[ 1.296049] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 1.300293] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 1.308694] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 1.313628] pci 0000:00:01.3: [8086:7113] type 00 class 0x000000
[ 1.320739] pci 0000:00:01.3: quirk: [io 0xb000-0xb03f] claimed by PIIX4 ACPI
[ 1.324071] pci 0000:00:01.3: quirk: [io 0xb100-0xb10f] claimed by PIIX4 SMB
[ 1.328146] pci 0000:00:01.3: PIIX4 devres E PIO at fff0-ffff
[ 1.332071] pci 0000:00:01.3: PIIX4 devres F MMIO at ffc00000-ffffffff
[ 1.336073] pci 0000:00:01.3: PIIX4 devres G PIO at fff0-ffff
[ 1.340074] pci 0000:00:01.3: PIIX4 devres H MMIO at ffc00000-ffffffff
[ 1.344071] pci 0000:00:01.3: PIIX4 devres I PIO at fff0-ffff
[ 1.348072] pci 0000:00:01.3: PIIX4 devres J PIO at fff0-ffff
[ 1.352051] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x170 took 31250 usecs
[ 1.357225] pci 0000:00:03.0: [1d0f:1111] type 00 class 0x030000
[ 1.360529] pci 0000:00:03.0: reg 0x10: [mem 0xfe400000-0xfe7fffff pref]
[ 1.365399] pci 0000:00:03.0: reg 0x30: [mem 0xfebd0000-0xfebdffff pref]
[ 1.372302] pci 0000:00:04.0: [1d0f:8061] type 00 class 0x010802
[ 1.378272] pci 0000:00:04.0: reg 0x10: [mem 0xfebf0000-0xfebf3fff]
[ 1.395149] pci 0000:00:05.0: [1d0f:ec20] type 00 class 0x020000
[ 1.399306] pci 0000:00:05.0: reg 0x10: [mem 0xfebf4000-0xfebf7fff]
[ 1.405945] pci 0000:00:05.0: reg 0x18: [mem 0xfe800000-0xfe8fffff pref]
[ 1.416055] pci 0000:00:05.0: reg 0x20: [mem 0xfebe0000-0xfebeffff]
[ 1.438985] pci 0000:00:1f.0: [1d0f:cd01] type 00 class 0x010802
[ 1.445202] pci 0000:00:1f.0: reg 0x10: [mem 0xfebf8000-0xfebfbfff]
[ 1.453876] pci 0000:00:1f.0: reg 0x18: [mem 0xfe900000-0xfe901fff pref]
[ 1.467331] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[ 1.468229] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[ 1.472224] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[ 1.476250] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[ 1.480143] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[ 1.484441] iommu: Default domain type: Translated
[ 1.488090] pci 0000:00:03.0: vgaarb: setting as boot VGA device
[ 1.492045] pci 0000:00:03.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[ 1.492050] pci 0000:00:03.0: vgaarb: bridge control possible
[ 1.496047] vgaarb: loaded
[ 1.500219] SCSI subsystem initialized
[ 1.504098] libata version 3.00 loaded.
[ 1.504098] ACPI: bus type USB registered
[ 1.508063] usbcore: registered new interface driver usbfs
[ 1.512058] usbcore: registered new interface driver hub
[ 1.516073] usbcore: registered new device driver usb
[ 1.520069] pps_core: LinuxPPS API ver. 1 registered
[ 1.524047] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[ 1.528051] PTP clock support registered
[ 1.532143] EDAC MC: Ver: 3.0.0
[ 1.536374] NetLabel: Initializing
[ 1.540048] NetLabel: domain hash size = 128
[ 1.544047] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO
[ 1.548062] NetLabel: unlabeled traffic allowed by default
[ 1.552077] PCI: Using ACPI for IRQ routing
[ 1.556048] PCI: pci_cache_line_size set to 64 bytes
[ 1.556271] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 1.556273] e820: reserve RAM buffer [mem 0xbfffa000-0xbfffffff]
[ 1.556288] clocksource: Switched to clocksource kvm-clock
[ 1.574117] VFS: Disk quotas dquot_6.6.0
[ 1.577898] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 1.583143] AppArmor: AppArmor Filesystem Enabled
[ 1.587053] pnp: PnP ACPI init
[ 1.590259] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[ 1.590301] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[ 1.590327] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[ 1.590402] pnp 00:03: Plug and Play ACPI device, IDs PNP0400 (active)
[ 1.590467] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[ 1.590940] pnp: PnP ACPI: found 5 devices
[ 1.603186] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 1.610307] NET: Registered protocol family 2
[ 1.614103] tcp_listen_portaddr_hash hash table entries: 4096 (order: 4, 65536 bytes, linear)
[ 1.620984] TCP established hash table entries: 65536 (order: 7, 524288 bytes, linear)
[ 1.627788] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes, linear)
[ 1.634355] TCP: Hash tables configured (established 65536 bind 65536)
[ 1.638993] MPTCP token hash table entries: 8192 (order: 5, 196608 bytes, linear)
[ 1.645621] UDP hash table entries: 4096 (order: 5, 131072 bytes, linear)
[ 1.650374] UDP-Lite hash table entries: 4096 (order: 5, 131072 bytes, linear)
[ 1.656851] NET: Registered protocol family 1
[ 1.660451] NET: Registered protocol family 44
[ 1.664180] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 1.668693] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 1.673282] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 1.678249] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
[ 1.683251] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 1.687716] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 1.692396] pci 0000:00:03.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[ 1.699605] PCI: CLS 0 bytes, default 64
[ 1.703367] Trying to unpack rootfs image as initramfs...
[ 1.917923] Freeing initrd memory: 81184K
[ 1.921648] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[ 1.926340] software IO TLB: mapped [mem 0xbbffa000-0xbfffa000] (64MB)
[ 1.931218] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1fb5a559600, max_idle_ns: 440795315627 ns
[ 1.939045] clocksource: Switched to clocksource tsc
[ 1.943190] check: Scanning for low memory corruption every 60 seconds
[ 1.948395] Initialise system trusted keyrings
[ 1.952178] Key type blacklist registered
[ 1.955841] workingset: timestamp_bits=36 max_order=21 bucket_order=0
[ 1.961716] zbud: loaded
[ 1.964897] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[ 1.969475] fuse: init (API version 7.31)
[ 1.973231] integrity: Platform Keyring initialized
[ 1.989507] Key type asymmetric registered
[ 1.993090] Asymmetric key parser 'x509' registered
[ 1.997054] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
[ 2.003874] io scheduler mq-deadline registered
[ 2.007849] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 2.012681] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 2.019070] ACPI: Power Button [PWRF]
[ 2.022475] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
[ 2.028979] ACPI: Sleep Button [SLPF]
[ 2.032683] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[ 2.066181] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 2.075440] Linux agpgart interface v0.103
[ 2.119754] loop: module loaded
[ 2.123206] libphy: Fixed MDIO Bus: probed
[ 2.126691] tun: Universal TUN/TAP device driver, 1.6
[ 2.130682] PPP generic driver version 2.4.2
[ 2.134367] VFIO - User Level meta-driver version: 0.3
[ 2.138416] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 2.143051] ehci-pci: EHCI PCI platform driver
[ 2.146733] ehci-platform: EHCI generic platform driver
[ 2.150719] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 2.155125] ohci-pci: OHCI PCI platform driver
[ 2.158778] ohci-platform: OHCI generic platform driver
[ 2.162944] uhci_hcd: USB Universal Host Controller Interface driver
[ 2.167508] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 2.174653] i8042: Warning: Keylock active
[ 2.179085] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 2.182994] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 2.187124] mousedev: PS/2 mouse device common for all mice
[ 2.191856] rtc_cmos 00:00: RTC can wake from S4
[ 2.196410] rtc_cmos 00:00: registered as rtc0
[ 2.200240] rtc_cmos 00:00: setting system clock to 2020-10-21T12:54:17 UTC (1603284857)
[ 2.207144] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
[ 2.211572] i2c /dev entries driver
[ 2.214802] device-mapper: uevent: version 1.0.3
[ 2.218606] device-mapper: ioctl: 4.42.0-ioctl (2020-02-27) initialised: dm-devel@redhat.com
[ 2.225564] platform eisa.0: Probing EISA bus 0
[ 2.229279] platform eisa.0: EISA: Cannot allocate resource for mainboard
[ 2.233980] platform eisa.0: Cannot allocate resource for EISA slot 1
[ 2.238473] platform eisa.0: Cannot allocate resource for EISA slot 2
[ 2.243018] platform eisa.0: Cannot allocate resource for EISA slot 3
[ 2.247560] platform eisa.0: Cannot allocate resource for EISA slot 4
[ 2.252141] platform eisa.0: Cannot allocate resource for EISA slot 5
[ 2.256663] platform eisa.0: Cannot allocate resource for EISA slot 6
[ 2.261241] platform eisa.0: Cannot allocate resource for EISA slot 7
[ 2.265807] platform eisa.0: Cannot allocate resource for EISA slot 8
[ 2.270373] platform eisa.0: EISA: Detected 0 cards
[ 2.274267] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.278683] drop_monitor: Initializing network drop monitor service
[ 2.283334] NET: Registered protocol family 10
[ 2.292415] Segment Routing with IPv6
[ 2.295756] NET: Registered protocol family 17
[ 2.299497] Key type dns_resolver registered
[ 2.303444] IPI shorthand broadcast: enabled
[ 2.307089] sched_clock: Marking stable (1646920158, 660140402)->(2395714425, -88653865)
[ 2.313991] registered taskstats version 1
[ 2.317521] Loading compiled-in X.509 certificates
[ 2.322108] Loaded X.509 cert 'Build time autogenerated kernel key: 9902a396bd6dc86a8f9804f6776b75584aa43b32'
[ 2.329643] zswap: loaded using pool lzo/zbud
[ 2.333589] Key type ._fscrypt registered
[ 2.337094] Key type .fscrypt registered
[ 2.340493] Key type fscrypt-provisioning registered
[ 2.346748] Key type encrypted registered
[ 2.350204] AppArmor: AppArmor sha1 policy hashing enabled
[ 2.354298] ima: No TPM chip found, activating TPM-bypass!
[ 2.358384] ima: Allocated hash algorithm: sha1
[ 2.362208] ima: No architecture policies found
[ 2.365926] evm: Initialising EVM extended attributes:
[ 2.369900] evm: security.selinux
[ 2.373093] evm: security.SMACK64
[ 2.376234] evm: security.SMACK64EXEC
[ 2.379537] evm: security.SMACK64TRANSMUTE
[ 2.383079] evm: security.SMACK64MMAP
[ 2.386436] evm: security.apparmor
[ 2.389678] evm: security.ima
[ 2.392721] evm: security.capability
[ 2.395989] evm: HMAC attrs: 0x1
[ 2.399376] PM: Magic number: 8:765:936
[ 2.403227] RAS: Correctable Errors collector initialized.
[ 2.410784] Freeing unused decrypted memory: 2040K
[ 2.415016] Freeing unused kernel image (initmem) memory: 2640K
[ 2.432068] Write protecting the kernel read-only data: 26624k
[ 2.436901] Freeing unused kernel image (text/rodata gap) memory: 2044K
[ 2.441837] Freeing unused kernel image (rodata/data gap) memory: 1544K
[ 2.491947] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[ 2.496558] Run /init as init process
[ 2.499892] with arguments:
[ 2.499893] /init
[ 2.499893] with environment:
[ 2.499894] HOME=/
[ 2.499894] TERM=linux
[ 2.499895] BOOT_IMAGE=/boot/vmlinuz-5.9.1-050901-generic
[ 2.593067] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100, revision 255
[ 2.632673] ena: ena device version: 0.10
[ 2.636667] ena: ena controller version: 0.0.1 implementation version 1
[ 2.642895] cryptd: max_cpu_qlen set to 1000
[ 2.661467] nvme nvme0: pci function 0000:00:04.0
[ 2.666171] PCI Interrupt Link [LNKD] enabled at IRQ 11
[ 2.673199] AVX2 version of gcm_enc/dec engaged.
[ 2.673779] nvme nvme1: pci function 0000:00:1f.0
[ 2.677481] AES CTR mode by8 optimization enabled
[ 2.688660] nvme nvme0: 2/0/0 default/read/poll queues
[ 2.693219] nvme nvme1: 2/0/0 default/read/poll queues
[ 2.697902] nvme0n1: p1
[ 2.698436] ena 0000:00:05.0: Elastic Network Adapter (ENA) found at mem febf4000, mac addr 06:9f:9b:4b:81:36, Placement policy: Low Latency
[ 2.713058] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input2
[ 2.722273] ena 0000:00:05.0 ens5: renamed from eth0
[ 3.587397] input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input4
[ 4.328060] raid6: avx2x4 gen() 15358 MB/s
[ 4.396060] raid6: avx2x4 xor() 6712 MB/s
[ 4.464059] raid6: avx2x2 gen() 15596 MB/s
[ 4.532059] raid6: avx2x2 xor() 9973 MB/s
[ 4.600058] raid6: avx2x1 gen() 14831 MB/s
[ 4.668058] raid6: avx2x1 xor() 9501 MB/s
[ 4.736059] raid6: sse2x4 gen() 10792 MB/s
[ 4.804059] raid6: sse2x4 xor() 5938 MB/s
[ 4.872059] raid6: sse2x2 gen() 12190 MB/s
[ 4.940060] raid6: sse2x2 xor() 7534 MB/s
[ 5.008059] raid6: sse2x1 gen() 9416 MB/s
[ 5.076060] raid6: sse2x1 xor() 5743 MB/s
[ 5.079600] raid6: using algorithm avx2x2 gen() 15596 MB/s
[ 5.083699] raid6: .... xor() 9973 MB/s, rmw enabled
[ 5.087603] raid6: using avx2x2 recovery algorithm
[ 5.092525] xor: automatically using best checksumming function avx
[ 5.098231] async_tx: api initialized (async)
[ 5.157598] Btrfs loaded, crc32c=crc32c-intel
[ 5.189828] EXT4-fs (nvme0n1p1): mounted filesystem with ordered data mode. Opts: (null)
[ 5.491461] systemd[1]: Inserted module 'autofs4'
[ 5.512540] systemd[1]: systemd 245.4-4ubuntu3 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=hybrid)
[ 5.528635] systemd[1]: Detected virtualization kvm.
[ 5.532580] systemd[1]: Detected architecture x86-64.
[ 5.561798] systemd[1]: Set hostname to <ip-172-20-52-180>.
[ 5.751948] systemd[1]: /lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
[ 5.821914] systemd[1]: /lib/systemd/system/docker.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/docker.sock → /run/docker.sock; please update the unit file accordingly.
[ 5.890437] systemd[1]: Created slice system-modprobe.slice.
[ 5.896439] systemd[1]: Created slice system-serial\x2dgetty.slice.
[ 5.902793] systemd[1]: Created slice User and Session Slice.
[ 5.908365] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 5.916602] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 5.925573] systemd[1]: Reached target User and Group Name Lookups.
[ 5.931463] systemd[1]: Reached target Slices.
[ 5.936115] systemd[1]: Reached target Swap.
[ 5.940722] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[ 5.946836] systemd[1]: Listening on LVM2 poll daemon socket.
[ 5.952523] systemd[1]: Listening on multipathd control socket.
[ 5.961380] systemd[1]: Listening on RPCbind Server Activation Socket.
[ 5.967508] systemd[1]: Listening on Syslog Socket.
[ 5.972594] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 5.978792] systemd[1]: Listening on Journal Audit Socket.
[ 5.984275] systemd[1]: Listening on Journal Socket (/dev/log).
[ 5.989963] systemd[1]: Listening on Journal Socket.
[ 5.995094] systemd[1]: Listening on Network Service Netlink Socket.
[ 6.001223] systemd[1]: Listening on udev Control Socket.
[ 6.006758] systemd[1]: Listening on udev Kernel Socket.
[ 6.013192] systemd[1]: Mounting Huge Pages File System...
[ 6.019594] systemd[1]: Mounting POSIX Message Queue File System...
[ 6.026379] systemd[1]: Mounting RPC Pipe File System...
[ 6.033163] systemd[1]: Mounting Kernel Debug File System...
[ 6.039650] systemd[1]: Mounting Kernel Trace File System...
[ 6.046925] systemd[1]: Starting Journal Service...
[ 6.053277] systemd[1]: Starting Set the console keyboard layout...
[ 6.066504] systemd[1]: Starting Create list of static device nodes for the current kernel...
[ 6.077642] systemd[1]: Starting Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling...
[ 6.080172] RPC: Registered named UNIX socket transport module.
[ 6.091219] RPC: Registered udp transport module.
[ 6.095558] RPC: Registered tcp transport module.
[ 6.095559] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 6.111001] systemd[1]: Starting Load Kernel Module drm...
[ 6.120526] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[ 6.138923] systemd[1]: Starting Load Kernel Modules...
[ 6.145794] systemd[1]: Starting Remount Root and Kernel File Systems...
[ 6.160352] systemd[1]: Starting udev Coldplug all Devices...
[ 6.169318] systemd[1]: Starting Uncomplicated firewall...
[ 6.179540] systemd[1]: Mounted Huge Pages File System.
[ 6.187548] EXT4-fs (nvme0n1p1): re-mounted. Opts: discard
[ 6.233709] systemd[1]: Mounted POSIX Message Queue File System.
[ 6.241004] systemd[1]: Mounted RPC Pipe File System.
[ 6.252392] systemd[1]: Mounted Kernel Debug File System.
[ 6.258752] systemd[1]: Mounted Kernel Trace File System.
[ 6.266061] systemd[1]: Finished Create list of static device nodes for the current kernel.
[ 6.282571] systemd[1]: Finished Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
[ 6.297874] systemd[1]: Started Journal Service.
[ 6.345035] systemd-journald[344]: Received client request to flush runtime journal.
[ 6.683066] parport_pc 00:03: reported by Plug and Play ACPI
[ 6.704137] Decoding supported only on Scalable MCA processors.
[ 6.744852] Decoding supported only on Scalable MCA processors.
[ 6.789613] ppdev: user-space parallel port driver
[ 7.157253] alua: device handler registered
[ 7.158723] emc: device handler registered
[ 7.160243] rdac: device handler registered
[ 7.740709] audit: type=1400 audit(1603284863.035:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=477 comm="apparmor_parser"
[ 7.742264] audit: type=1400 audit(1603284863.035:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=477 comm="apparmor_parser"
[ 7.743608] audit: type=1400 audit(1603284863.035:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=477 comm="apparmor_parser"
[ 7.746788] audit: type=1400 audit(1603284863.039:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/{,usr/}sbin/dhclient" pid=477 comm="apparmor_parser"
[ 7.825551] audit: type=1400 audit(1603284863.119:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=481 comm="apparmor_parser"
[ 7.866407] audit: type=1400 audit(1603284863.159:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/snapd/snap-confine" pid=476 comm="apparmor_parser"
[ 7.867638] audit: type=1400 audit(1603284863.159:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=476 comm="apparmor_parser"
[ 7.913030] audit: type=1400 audit(1603284863.207:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=483 comm="apparmor_parser"
[ 7.914354] audit: type=1400 audit(1603284863.207:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=483 comm="apparmor_parser"
[ 8.049437] audit: type=1400 audit(1603284863.343:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=485 comm="apparmor_parser"
[ 10.776073] IPv6: ADDRCONF(NETDEV_CHANGE): ens5: link becomes ready
[ 13.650285] bpfilter: Loaded bpfilter_umh pid 629
[ 13.650561] Started bpfilter
[ 14.483190] kauditd_printk_skb: 23 callbacks suppressed
[ 14.483192] audit: type=1400 audit(1603284869.319:35): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker-default" pid=868 comm="apparmor_parser"
[ 14.696024] Initializing XFRM netlink socket
[ 14.746873] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[ 15.034087] process 'docker/tmp/qemu-check041567443/check' started with executable stack
[ 15.396682] audit: type=1400 audit(1603284870.235:36): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/snap/core/9066/usr/lib/snapd/snap-confine" pid=977 comm="apparmor_parser"
[ 15.412107] audit: type=1400 audit(1603284870.251:37): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/snap/core/9066/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=977 comm="apparmor_parser"
[ 15.462021] audit: type=1400 audit(1603284870.299:38): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=979 comm="apparmor_parser"
[ 15.464649] audit: type=1400 audit(1603284870.303:39): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.benchmark" pid=981 comm="apparmor_parser"
[ 15.464941] audit: type=1400 audit(1603284870.303:40): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.activate" pid=980 comm="apparmor_parser"
[ 15.467292] audit: type=1400 audit(1603284870.303:41): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.buginfo" pid=982 comm="apparmor_parser"
[ 15.470003] audit: type=1400 audit(1603284870.307:42): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.daemon" pid=984 comm="apparmor_parser"
[ 15.472766] audit: type=1400 audit(1603284870.311:43): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.hook.configure" pid=985 comm="apparmor_parser"
[ 15.475207] audit: type=1400 audit(1603284870.311:44): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.lxd.hook.install" pid=986 comm="apparmor_parser"
[ 17.083633] Bridge firewalling registered
[ 101.735059] kmem.limit_in_bytes is deprecated and will be removed. Please report your usecase to linux-mm@kvack.org if you depend on this functionality.
[ 102.399825] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[ 103.179138] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[ 103.179153] IPVS: Connection hash table configured (size=4096, memory=64Kbytes)
[ 103.179202] IPVS: ipvs loaded.
[ 103.184872] IPVS: [rr] scheduler registered.
[ 103.188372] IPVS: [wrr] scheduler registered.
[ 103.192147] IPVS: [sh] scheduler registered.
[ 152.060524] SGI XFS with ACLs, security attributes, realtime, quota, no debug enabled
[ 152.068152] JFS: nTxBlock = 8192, nTxLock = 65536
[ 152.088472] ntfs: driver 2.1.32 [Flags: R/O MODULE].
[ 152.104318] QNX4 filesystem 0.2.3 registered.
[ 369.376653] cbr0: port 1(vethbd9f5f2d) entered blocking state
[ 369.376656] cbr0: port 1(vethbd9f5f2d) entered disabled state
[ 369.376781] device vethbd9f5f2d entered promiscuous mode
[ 369.376831] cbr0: port 1(vethbd9f5f2d) entered blocking state
[ 369.376833] cbr0: port 1(vethbd9f5f2d) entered forwarding state
[ 369.393593] device cbr0 entered promiscuous mode
[ 3222.990144] IPv6: ADDRCONF(NETDEV_CHANGE): vethc8721731: link becomes ready
[ 3222.991096] cbr0: port 2(vethc8721731) entered blocking state
[ 3222.991098] cbr0: port 2(vethc8721731) entered disabled state
[ 3222.991724] device vethc8721731 entered promiscuous mode
[ 3222.991782] cbr0: port 2(vethc8721731) entered blocking state
[ 3222.991784] cbr0: port 2(vethc8721731) entered forwarding state
[34830.187433] kauditd_printk_skb: 11 callbacks suppressed
[34830.187435] audit: type=1400 audit(1603319683.220:56): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/snap/core/10185/usr/lib/snapd/snap-confine" pid=891742 comm="apparmor_parser"
[34830.211608] audit: type=1400 audit(1603319683.244:57): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/snap/core/10185/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=891742 comm="apparmor_parser"
[34830.253075] audit: type=1400 audit(1603319683.284:58): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.core.hook.configure" pid=891744 comm="apparmor_parser"
[34830.281290] audit: type=1400 audit(1603319683.312:59): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.core" pid=891746 comm="apparmor_parser"
[34830.281651] audit: type=1400 audit(1603319683.312:60): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.lxd" pid=891747 comm="apparmor_parser"
[34830.284337] audit: type=1400 audit(1603319683.316:61): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.benchmark" pid=891749 comm="apparmor_parser"
[34830.286009] audit: type=1400 audit(1603319683.316:62): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.buginfo" pid=891750 comm="apparmor_parser"
[34830.288196] audit: type=1400 audit(1603319683.320:63): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.check-kernel" pid=891751 comm="apparmor_parser"
[34830.291907] audit: type=1400 audit(1603319683.324:64): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.activate" pid=891748 comm="apparmor_parser"
[34830.301099] audit: type=1400 audit(1603319683.332:65): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.hook.configure" pid=891753 comm="apparmor_parser"
[34841.094827] kauditd_printk_skb: 27 callbacks suppressed
[34841.094829] audit: type=1400 audit(1603319694.128:93): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.amazon-ssm-agent.amazon-ssm-agent" pid=892051 comm="apparmor_parser"
[34841.095061] audit: type=1400 audit(1603319694.128:94): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.amazon-ssm-agent.ssm-cli" pid=892052 comm="apparmor_parser"
[34841.111655] audit: type=1400 audit(1603319694.148:95): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.amazon-ssm-agent" pid=892054 comm="apparmor_parser"
[34845.928172] audit: type=1400 audit(1603319698.964:96): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/core/10185/usr/lib/snapd/snap-confine" pid=892244 comm="apparmor_parser"
[34845.928178] audit: type=1400 audit(1603319698.964:97): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/core/10185/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=892244 comm="apparmor_parser"
[34845.934828] audit: type=1400 audit(1603319698.968:98): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.activate" pid=892246 comm="apparmor_parser"
[34845.937439] audit: type=1400 audit(1603319698.972:99): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.benchmark" pid=892247 comm="apparmor_parser"
[34845.940800] audit: type=1400 audit(1603319698.976:100): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.check-kernel" pid=892249 comm="apparmor_parser"
[34845.943435] audit: type=1400 audit(1603319698.976:101): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.buginfo" pid=892248 comm="apparmor_parser"
[34845.943440] audit: type=1400 audit(1603319698.976:102): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.lxd.daemon" pid=892250 comm="apparmor_parser"
[85007.740233] cbr0: port 1(vethbd9f5f2d) entered disabled state
[85007.745594] device vethbd9f5f2d left promiscuous mode
[85007.745609] cbr0: port 1(vethbd9f5f2d) entered disabled state
[85063.747779] nvme nvme2: queue_size 128 > ctrl sqsize 64, clamping down
[85063.749781] nvme nvme2: creating 2 I/O queues.
[85063.768726] nvme nvme2: mapped 2/0/0 default/read/poll queues.
[85063.769370] nvme nvme2: new ctrl: NQN "nqn.2019-05.io.openebs:nexus-fbceb112-8f44-4004-94a8-8c6935218cd0", addr 172.20.34.25:8420
[85064.434409] EXT4-fs (nvme2n1): mounted filesystem with ordered data mode. Opts: (null)
[85065.651696] cbr0: port 1(veth4664f6f4) entered blocking state
[85065.651699] cbr0: port 1(veth4664f6f4) entered disabled state
[85065.652840] device veth4664f6f4 entered promiscuous mode
[85065.653366] cbr0: port 1(veth4664f6f4) entered blocking state
[85065.653368] cbr0: port 1(veth4664f6f4) entered forwarding state
[85828.946304] nvme nvme2: Removing ctrl: NQN "nqn.2019-05.io.openebs:nexus-fbceb112-8f44-4004-94a8-8c6935218cd0"
[85830.824287] cbr0: port 1(veth4664f6f4) entered disabled state
[85830.829665] device veth4664f6f4 left promiscuous mode
[85830.829670] cbr0: port 1(veth4664f6f4) entered disabled state
[86065.370968] IPv6: ADDRCONF(NETDEV_CHANGE): veth08d81e6e: link becomes ready
[86065.373696] cbr0: port 1(veth08d81e6e) entered blocking state
[86065.373699] cbr0: port 1(veth08d81e6e) entered disabled state
[86065.374096] device veth08d81e6e entered promiscuous mode
[86065.374448] cbr0: port 1(veth08d81e6e) entered blocking state
[86065.374450] cbr0: port 1(veth08d81e6e) entered forwarding state
[87655.635950] cbr0: port 1(veth08d81e6e) entered disabled state
[87655.641193] device veth08d81e6e left promiscuous mode
[87655.641198] cbr0: port 1(veth08d81e6e) entered disabled state
[88265.524954] IPv6: ADDRCONF(NETDEV_CHANGE): veth3e20aa4c: link becomes ready
[88265.527668] cbr0: port 1(veth3e20aa4c) entered blocking state
[88265.527671] cbr0: port 1(veth3e20aa4c) entered disabled state
[88265.528033] device veth3e20aa4c entered promiscuous mode
[88265.528380] cbr0: port 1(veth3e20aa4c) entered blocking state
[88265.528383] cbr0: port 1(veth3e20aa4c) entered forwarding state
[88302.347217] nvme nvme2: queue_size 128 > ctrl sqsize 64, clamping down
[88302.347544] nvme nvme2: creating 2 I/O queues.
[88302.369919] nvme nvme2: mapped 2/0/0 default/read/poll queues.
[88302.380869] nvme nvme2: new ctrl: NQN "nqn.2019-05.io.openebs:nexus-4c89ea3f-1cb0-41a4-b622-15b2c461b382", addr 172.20.34.25:8420
[88302.787550] EXT4-fs (nvme2n1): mounted filesystem with ordered data mode. Opts: (null)
[88303.769763] IPv6: ADDRCONF(NETDEV_CHANGE): vethf511b0a9: link becomes ready
[88303.772581] cbr0: port 3(vethf511b0a9) entered blocking state
[88303.772583] cbr0: port 3(vethf511b0a9) entered disabled state
[88303.774009] device vethf511b0a9 entered promiscuous mode
[88303.777211] cbr0: port 3(vethf511b0a9) entered blocking state
[88303.777214] cbr0: port 3(vethf511b0a9) entered forwarding state
[90617.470746] cbr0: port 3(vethf511b0a9) entered disabled state
[90617.475893] device vethf511b0a9 left promiscuous mode
[90617.475898] cbr0: port 3(vethf511b0a9) entered disabled state
[90619.781171] nvme nvme2: Removing ctrl: NQN "nqn.2019-05.io.openebs:nexus-4c89ea3f-1cb0-41a4-b622-15b2c461b382"
[91020.100518] nvme nvme2: queue_size 128 > ctrl sqsize 64, clamping down
[91020.100783] nvme nvme2: creating 2 I/O queues.
[91020.115406] nvme nvme2: mapped 2/0/0 default/read/poll queues.
[91020.116332] nvme nvme2: new ctrl: NQN "nqn.2019-05.io.openebs:nexus-83627c0a-20a2-4125-a698-0a4ba754a80f", addr 172.20.34.25:8420
[91020.544897] EXT4-fs (nvme2n1): mounted filesystem with ordered data mode. Opts: (null)
[91021.441733] IPv6: ADDRCONF(NETDEV_CHANGE): veth7e157fef: link becomes ready
[91021.444746] cbr0: port 3(veth7e157fef) entered blocking state
[91021.444749] cbr0: port 3(veth7e157fef) entered disabled state
[91021.445427] device veth7e157fef entered promiscuous mode
[91021.445793] cbr0: port 3(veth7e157fef) entered blocking state
[91021.445795] cbr0: port 3(veth7e157fef) entered forwarding state
[91355.455641] INFO: task jbd2/nvme2n1-8:1787878 blocked for more than 120 seconds.
[91355.459660] Not tainted 5.9.1-050901-generic #202010170731
[91355.462924] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.467176] task:jbd2/nvme2n1-8 state:D stack: 0 pid:1787878 ppid: 2 flags:0x00004000
[91355.467180] Call Trace:
[91355.467188] __schedule+0x1fe/0x5e0
[91355.467191] schedule+0x55/0xc0
[91355.467193] io_schedule+0x45/0x70
[91355.467197] blk_mq_get_tag+0x11b/0x270
[91355.467200] ? wait_woken+0x80/0x80
[91355.467203] __blk_mq_alloc_request+0x82/0x120
[91355.467205] blk_mq_submit_bio+0x139/0x5f0
[91355.467208] __submit_bio_noacct+0x2ee/0x320
[91355.467210] submit_bio_noacct+0x4d/0x90
[91355.467212] submit_bio+0x4f/0x1b0
[91355.467214] ? bio_add_page+0x6a/0x90
[91355.467217] submit_bh_wbc+0x195/0x1c0
[91355.467219] submit_bh+0x13/0x20
[91355.467222] jbd2_journal_commit_transaction+0x798/0x1454
[91355.467224] ? sched_clock+0x9/0x10
[91355.467228] ? del_timer_sync+0x6c/0xb0
[91355.467231] kjournald2+0xa9/0x280
[91355.467233] ? wait_woken+0x80/0x80
[91355.467235] kthread+0x12f/0x150
[91355.467237] ? jbd2_journal_init_inode+0x120/0x120
[91355.467239] ? __kthread_bind_mask+0x70/0x70
[91355.467242] ret_from_fork+0x22/0x30
[91355.467248] INFO: task fio:1790564 blocked for more than 120 seconds.
[91355.470825] Not tainted 5.9.1-050901-generic #202010170731
[91355.474139] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.478286] task:fio state:D stack: 0 pid:1790564 ppid:1788387 flags:0x00000004
[91355.478289] Call Trace:
[91355.478293] __schedule+0x1fe/0x5e0
[91355.478296] schedule+0x55/0xc0
[91355.478298] io_schedule+0x45/0x70
[91355.478300] blk_mq_get_tag+0x11b/0x270
[91355.478302] ? wait_woken+0x80/0x80
[91355.478304] __blk_mq_alloc_request+0x82/0x120
[91355.478306] blk_mq_submit_bio+0x139/0x5f0
[91355.478309] __submit_bio_noacct+0x2ee/0x320
[91355.478311] submit_bio_noacct+0x4d/0x90
[91355.478313] submit_bio+0x4f/0x1b0
[91355.478316] iomap_dio_submit_bio+0x86/0x90
[91355.478318] iomap_dio_bio_actor+0x191/0x3d0
[91355.478320] iomap_dio_actor+0x2a/0x80
[91355.478321] iomap_apply+0x10c/0x340
[91355.478323] ? iomap_dio_rw+0x22a/0x4f0
[91355.478325] ? iomap_dio_inline_actor+0x130/0x130
[91355.478327] iomap_dio_rw+0x22a/0x4f0
[91355.478329] ? iomap_dio_inline_actor+0x130/0x130
[91355.478332] ext4_dio_write_iter+0x1c3/0x390
[91355.478334] ext4_file_write_iter+0x3f/0x50
[91355.478336] aio_write+0xf8/0x1b0
[91355.478340] ? do_shared_fault+0x6b/0xb0
[91355.478342] ? do_fault+0x1a5/0x1d0
[91355.478343] ? _cond_resched+0x1a/0x50
[91355.478345] ? io_submit_one+0x6b/0x390
[91355.478347] __io_submit_one.constprop.0+0x176/0x1f0
[91355.478349] io_submit_one+0xde/0x390
[91355.478351] __x64_sys_io_submit+0x86/0x170
[91355.478354] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.478356] ? irqentry_exit_to_user_mode+0x9/0x20
[91355.478359] do_syscall_64+0x38/0x90
[91355.478361] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.478363] RIP: 0033:0x7f04a9d7c979
[91355.478364] Code: Bad RIP value.
[91355.478365] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.478367] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.478368] RDX: 000000000063ceb0 RSI: 0000000000000001 RDI: 00007f045bdf9000
[91355.478369] RBP: 00007f045bdf9000 R08: 0000000000000000 R09: 0000000000000000
[91355.478370] R10: 000000000063d478 R11: 0000000000000246 R12: 0000000000000001
[91355.478371] R13: 0000000000000000 R14: 000000000063ceb0 R15: 000000000063cc50
[91355.478374] INFO: task fio:1790566 blocked for more than 120 seconds.
[91355.481896] Not tainted 5.9.1-050901-generic #202010170731
[91355.485195] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.489385] task:fio state:D stack: 0 pid:1790566 ppid:1788387 flags:0x00000004
[91355.489388] Call Trace:
[91355.489392] __schedule+0x1fe/0x5e0
[91355.489394] schedule+0x55/0xc0
[91355.489396] io_schedule+0x45/0x70
[91355.489398] blk_mq_get_tag+0x11b/0x270
[91355.489401] ? wait_woken+0x80/0x80
[91355.489402] __blk_mq_alloc_request+0x82/0x120
[91355.489404] blk_mq_submit_bio+0x139/0x5f0
[91355.489407] __submit_bio_noacct+0x2ee/0x320
[91355.489409] submit_bio_noacct+0x4d/0x90
[91355.489410] submit_bio+0x4f/0x1b0
[91355.489413] iomap_dio_submit_bio+0x86/0x90
[91355.489414] iomap_dio_bio_actor+0x191/0x3d0
[91355.489416] iomap_dio_actor+0x2a/0x80
[91355.489418] iomap_apply+0x10c/0x340
[91355.489419] ? iomap_dio_rw+0x22a/0x4f0
[91355.489421] ? iomap_dio_inline_actor+0x130/0x130
[91355.489424] iomap_dio_rw+0x22a/0x4f0
[91355.489425] ? iomap_dio_inline_actor+0x130/0x130
[91355.489428] ext4_dio_write_iter+0x1c3/0x390
[91355.489430] ext4_file_write_iter+0x3f/0x50
[91355.489431] aio_write+0xf8/0x1b0
[91355.489433] ? aio_read_events_ring+0x209/0x280
[91355.489436] ? _cond_resched+0x1a/0x50
[91355.489437] ? io_submit_one+0x6b/0x390
[91355.489439] __io_submit_one.constprop.0+0x176/0x1f0
[91355.489441] io_submit_one+0xde/0x390
[91355.489443] __x64_sys_io_submit+0x86/0x170
[91355.489445] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.489447] do_syscall_64+0x38/0x90
[91355.489449] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.489451] RIP: 0033:0x7f04a9d7c979
[91355.489452] Code: Bad RIP value.
[91355.489453] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.489454] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.489455] RDX: 000000000063cf08 RSI: 0000000000000001 RDI: 00007f045bdf7000
[91355.489456] RBP: 00007f045bdf7000 R08: 0000000000000000 R09: 0000000000000018
[91355.489457] R10: 000000000063e078 R11: 0000000000000246 R12: 0000000000000001
[91355.489458] R13: 0000000000000000 R14: 000000000063cf08 R15: 000000000063cc90
[91355.489461] INFO: task fio:1790567 blocked for more than 120 seconds.
[91355.492967] Not tainted 5.9.1-050901-generic #202010170731
[91355.496244] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.500549] task:fio state:D stack: 0 pid:1790567 ppid:1788387 flags:0x00000004
[91355.500551] Call Trace:
[91355.500555] __schedule+0x1fe/0x5e0
[91355.500558] schedule+0x55/0xc0
[91355.500560] io_schedule+0x45/0x70
[91355.500562] blk_mq_get_tag+0x11b/0x270
[91355.500564] ? wait_woken+0x80/0x80
[91355.500566] __blk_mq_alloc_request+0x82/0x120
[91355.500568] blk_mq_submit_bio+0x139/0x5f0
[91355.500570] __submit_bio_noacct+0x2ee/0x320
[91355.500572] submit_bio_noacct+0x4d/0x90
[91355.500574] submit_bio+0x4f/0x1b0
[91355.500576] iomap_dio_submit_bio+0x86/0x90
[91355.500578] iomap_dio_bio_actor+0x191/0x3d0
[91355.500580] iomap_dio_actor+0x2a/0x80
[91355.500582] iomap_apply+0x10c/0x340
[91355.500583] ? iomap_dio_rw+0x22a/0x4f0
[91355.500585] ? iomap_dio_inline_actor+0x130/0x130
[91355.500587] iomap_dio_rw+0x22a/0x4f0
[91355.500589] ? iomap_dio_inline_actor+0x130/0x130
[91355.500591] ext4_dio_write_iter+0x1c3/0x390
[91355.500593] ext4_file_write_iter+0x3f/0x50
[91355.500595] aio_write+0xf8/0x1b0
[91355.500597] ? aio_read_events_ring+0x209/0x280
[91355.500599] ? _cond_resched+0x1a/0x50
[91355.500601] ? io_submit_one+0x6b/0x390
[91355.500603] __io_submit_one.constprop.0+0x176/0x1f0
[91355.500604] io_submit_one+0xde/0x390
[91355.500607] __x64_sys_io_submit+0x86/0x170
[91355.500609] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.500611] do_syscall_64+0x38/0x90
[91355.500613] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.500614] RIP: 0033:0x7f04a9d7c979
[91355.500615] Code: Bad RIP value.
[91355.500616] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.500618] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.500619] RDX: 000000000063cf48 RSI: 0000000000000001 RDI: 00007f045bdf6000
[91355.500620] RBP: 00007f045bdf6000 R08: 0000000000000000 R09: 0000000000000038
[91355.500620] R10: 000000000063e0b8 R11: 0000000000000246 R12: 0000000000000001
[91355.500621] R13: 0000000000000000 R14: 000000000063cf48 R15: 000000000063ccb0
[91355.500624] INFO: task fio:1790568 blocked for more than 120 seconds.
[91355.504139] Not tainted 5.9.1-050901-generic #202010170731
[91355.507412] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.511609] task:fio state:D stack: 0 pid:1790568 ppid:1788387 flags:0x00000004
[91355.511612] Call Trace:
[91355.511616] __schedule+0x1fe/0x5e0
[91355.511619] schedule+0x55/0xc0
[91355.511621] io_schedule+0x45/0x70
[91355.511623] blk_mq_get_tag+0x11b/0x270
[91355.511625] ? wait_woken+0x80/0x80
[91355.511627] __blk_mq_alloc_request+0x82/0x120
[91355.511629] blk_mq_submit_bio+0x139/0x5f0
[91355.511631] __submit_bio_noacct+0x2ee/0x320
[91355.511633] submit_bio_noacct+0x4d/0x90
[91355.511635] submit_bio+0x4f/0x1b0
[91355.511637] ? set_page_dirty_lock+0x40/0x60
[91355.511639] iomap_dio_submit_bio+0x86/0x90
[91355.511641] iomap_dio_bio_actor+0x191/0x3d0
[91355.511643] iomap_dio_actor+0x2a/0x80
[91355.511645] iomap_apply+0x10c/0x340
[91355.511646] ? iomap_dio_rw+0x22a/0x4f0
[91355.511648] ? iomap_dio_inline_actor+0x130/0x130
[91355.511650] iomap_dio_rw+0x22a/0x4f0
[91355.511652] ? iomap_dio_inline_actor+0x130/0x130
[91355.511654] ext4_file_read_iter+0x113/0x180
[91355.511656] aio_read+0xd4/0x160
[91355.511658] ? aio_read_events_ring+0x209/0x280
[91355.511660] ? _cond_resched+0x1a/0x50
[91355.511662] ? io_submit_one+0x6b/0x390
[91355.511664] __io_submit_one.constprop.0+0x107/0x1f0
[91355.511665] io_submit_one+0xde/0x390
[91355.511667] __x64_sys_io_submit+0x86/0x170
[91355.511670] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.511672] do_syscall_64+0x38/0x90
[91355.511674] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.511675] RIP: 0033:0x7f04a9d7c979
[91355.511676] Code: Bad RIP value.
[91355.511677] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.511678] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.511679] RDX: 000000000063cf60 RSI: 0000000000000001 RDI: 00007f045bdf5000
[91355.511680] RBP: 00007f045bdf5000 R08: 0000000000000000 R09: 0000000000000030
[91355.511681] R10: 000000000063dbb8 R11: 0000000000000246 R12: 0000000000000001
[91355.511682] R13: 0000000000000000 R14: 000000000063cf60 R15: 000000000063ccd0
[91355.511685] INFO: task fio:1790571 blocked for more than 120 seconds.
[91355.516871] Not tainted 5.9.1-050901-generic #202010170731
[91355.521829] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.529384] task:fio state:D stack: 0 pid:1790571 ppid:1788387 flags:0x00000004
[91355.529387] Call Trace:
[91355.529392] __schedule+0x1fe/0x5e0
[91355.529394] schedule+0x55/0xc0
[91355.529396] io_schedule+0x45/0x70
[91355.529398] blk_mq_get_tag+0x11b/0x270
[91355.529401] ? wait_woken+0x80/0x80
[91355.529403] __blk_mq_alloc_request+0x82/0x120
[91355.529405] blk_mq_submit_bio+0x139/0x5f0
[91355.529407] __submit_bio_noacct+0x2ee/0x320
[91355.529409] submit_bio_noacct+0x4d/0x90
[91355.529411] submit_bio+0x4f/0x1b0
[91355.529413] iomap_dio_submit_bio+0x86/0x90
[91355.529415] iomap_dio_bio_actor+0x191/0x3d0
[91355.529417] iomap_dio_actor+0x2a/0x80
[91355.529418] iomap_apply+0x10c/0x340
[91355.529420] ? iomap_dio_rw+0x22a/0x4f0
[91355.529421] ? iomap_dio_inline_actor+0x130/0x130
[91355.529424] iomap_dio_rw+0x22a/0x4f0
[91355.529425] ? iomap_dio_inline_actor+0x130/0x130
[91355.529428] ext4_dio_write_iter+0x1c3/0x390
[91355.529430] ext4_file_write_iter+0x3f/0x50
[91355.529432] aio_write+0xf8/0x1b0
[91355.529435] ? do_user_addr_fault+0x1ef/0x3c0
[91355.529438] ? _cond_resched+0x1a/0x50
[91355.529439] ? io_submit_one+0x6b/0x390
[91355.529441] __io_submit_one.constprop.0+0x176/0x1f0
[91355.529443] io_submit_one+0xde/0x390
[91355.529445] __x64_sys_io_submit+0x86/0x170
[91355.529447] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.529449] ? irqentry_exit_to_user_mode+0x9/0x20
[91355.529451] do_syscall_64+0x38/0x90
[91355.529453] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.529455] RIP: 0033:0x7f04a9d7c979
[91355.529455] Code: Bad RIP value.
[91355.529456] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.529458] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.529459] RDX: 000000000063cf90 RSI: 0000000000000001 RDI: 00007f045bdf2000
[91355.529460] RBP: 00007f045bdf2000 R08: 0000000000000000 R09: 0000000000000000
[91355.529460] R10: 000000000063ecf8 R11: 0000000000000246 R12: 0000000000000001
[91355.529461] R13: 0000000000000000 R14: 000000000063cf90 R15: 000000000063cd30
[91355.529464] INFO: task fio:1790572 blocked for more than 120 seconds.
[91355.534592] Not tainted 5.9.1-050901-generic #202010170731
[91355.539512] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.546978] task:fio state:D stack: 0 pid:1790572 ppid:1788387 flags:0x00000004
[91355.546980] Call Trace:
[91355.546985] __schedule+0x1fe/0x5e0
[91355.546987] schedule+0x55/0xc0
[91355.546989] io_schedule+0x45/0x70
[91355.546991] blk_mq_get_tag+0x11b/0x270
[91355.546993] ? wait_woken+0x80/0x80
[91355.546995] __blk_mq_alloc_request+0x82/0x120
[91355.546997] blk_mq_submit_bio+0x139/0x5f0
[91355.546999] __submit_bio_noacct+0x2ee/0x320
[91355.547001] submit_bio_noacct+0x4d/0x90
[91355.547003] submit_bio+0x4f/0x1b0
[91355.547006] ? set_page_dirty_lock+0x40/0x60
[91355.547008] iomap_dio_submit_bio+0x86/0x90
[91355.547009] iomap_dio_bio_actor+0x191/0x3d0
[91355.547012] iomap_dio_actor+0x2a/0x80
[91355.547013] iomap_apply+0x10c/0x340
[91355.547015] ? iomap_dio_rw+0x22a/0x4f0
[91355.547016] ? iomap_dio_inline_actor+0x130/0x130
[91355.547018] iomap_dio_rw+0x22a/0x4f0
[91355.547020] ? iomap_dio_inline_actor+0x130/0x130
[91355.547023] ext4_file_read_iter+0x113/0x180
[91355.547024] aio_read+0xd4/0x160
[91355.547027] ? do_user_addr_fault+0x1ef/0x3c0
[91355.547029] ? _cond_resched+0x1a/0x50
[91355.547031] ? io_submit_one+0x6b/0x390
[91355.547033] __io_submit_one.constprop.0+0x107/0x1f0
[91355.547035] io_submit_one+0xde/0x390
[91355.547037] __x64_sys_io_submit+0x86/0x170
[91355.547039] ? exit_to_user_mode_prepare+0xa2/0xd0
[91355.547041] do_syscall_64+0x38/0x90
[91355.547043] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.547045] RIP: 0033:0x7f04a9d7c979
[91355.547046] Code: Bad RIP value.
[91355.547046] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.547048] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.547049] RDX: 000000000063cfb8 RSI: 0000000000000001 RDI: 00007f045bdf1000
[91355.547050] RBP: 00007f045bdf1000 R08: 0000000000000000 R09: 0000000000000008
[91355.547051] R10: 000000000063eb78 R11: 0000000000000246 R12: 0000000000000001
[91355.547051] R13: 0000000000000000 R14: 000000000063cfb8 R15: 000000000063cd50
[91355.547054] INFO: task fio:1790573 blocked for more than 120 seconds.
[91355.552213] Not tainted 5.9.1-050901-generic #202010170731
[91355.557154] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91355.564623] task:fio state:D stack: 0 pid:1790573 ppid:1788387 flags:0x00000004
[91355.564626] Call Trace:
[91355.564630] __schedule+0x1fe/0x5e0
[91355.564633] schedule+0x55/0xc0
[91355.564635] io_schedule+0x45/0x70
[91355.564637] blk_mq_get_tag+0x11b/0x270
[91355.564639] ? wait_woken+0x80/0x80
[91355.564641] __blk_mq_alloc_request+0x82/0x120
[91355.564643] blk_mq_submit_bio+0x139/0x5f0
[91355.564645] __submit_bio_noacct+0x2ee/0x320
[91355.564647] submit_bio_noacct+0x4d/0x90
[91355.564649] submit_bio+0x4f/0x1b0
[91355.564651] iomap_dio_submit_bio+0x86/0x90
[91355.564653] iomap_dio_bio_actor+0x191/0x3d0
[91355.564655] iomap_dio_actor+0x2a/0x80
[91355.564656] iomap_apply+0x10c/0x340
[91355.564658] ? iomap_dio_rw+0x22a/0x4f0
[91355.564659] ? iomap_dio_inline_actor+0x130/0x130
[91355.564662] iomap_dio_rw+0x22a/0x4f0
[91355.564664] ? iomap_dio_inline_actor+0x130/0x130
[91355.564666] ext4_dio_write_iter+0x1c3/0x390
[91355.564668] ext4_file_write_iter+0x3f/0x50
[91355.564670] aio_write+0xf8/0x1b0
[91355.564673] ? do_user_addr_fault+0x1ef/0x3c0
[91355.564675] ? _cond_resched+0x1a/0x50
[91355.564676] ? io_submit_one+0x6b/0x390
[91355.564678] __io_submit_one.constprop.0+0x176/0x1f0
[91355.564680] io_submit_one+0xde/0x390
[91355.564682] __x64_sys_io_submit+0x86/0x170
[91355.564684] ? exit_to_user_mode_prepare+0x3b/0xd0
[91355.564686] ? irqentry_exit_to_user_mode+0x9/0x20
[91355.564688] do_syscall_64+0x38/0x90
[91355.564690] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91355.564692] RIP: 0033:0x7f04a9d7c979
[91355.564693] Code: Bad RIP value.
[91355.564694] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91355.564695] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91355.564696] RDX: 000000000063cfd0 RSI: 0000000000000001 RDI: 00007f045bdf0000
[91355.564697] RBP: 00007f045bdf0000 R08: 0000000000000000 R09: 0000000000000000
[91355.564698] R10: 000000000063ed38 R11: 0000000000000246 R12: 0000000000000001
[91355.564699] R13: 0000000000000000 R14: 000000000063cfd0 R15: 000000000063cd70
[91420.742071] cbr0: port 3(veth7e157fef) entered disabled state
[91420.755273] device veth7e157fef left promiscuous mode
[91420.755284] cbr0: port 3(veth7e157fef) entered disabled state
[91476.293958] INFO: task jbd2/nvme2n1-8:1787878 blocked for more than 241 seconds.
[91476.301238] Not tainted 5.9.1-050901-generic #202010170731
[91476.306140] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91476.313647] task:jbd2/nvme2n1-8 state:D stack: 0 pid:1787878 ppid: 2 flags:0x00004000
[91476.313651] Call Trace:
[91476.313659] __schedule+0x1fe/0x5e0
[91476.313664] schedule+0x55/0xc0
[91476.313666] io_schedule+0x45/0x70
[91476.313669] blk_mq_get_tag+0x11b/0x270
[91476.313673] ? wait_woken+0x80/0x80
[91476.313675] __blk_mq_alloc_request+0x82/0x120
[91476.313679] blk_mq_submit_bio+0x139/0x5f0
[91476.313682] __submit_bio_noacct+0x2ee/0x320
[91476.313684] submit_bio_noacct+0x4d/0x90
[91476.313686] submit_bio+0x4f/0x1b0
[91476.313688] ? bio_add_page+0x6a/0x90
[91476.313692] submit_bh_wbc+0x195/0x1c0
[91476.313694] submit_bh+0x13/0x20
[91476.313697] jbd2_journal_commit_transaction+0x798/0x1454
[91476.313701] ? sched_clock+0x9/0x10
[91476.313705] ? del_timer_sync+0x6c/0xb0
[91476.313708] kjournald2+0xa9/0x280
[91476.313710] ? wait_woken+0x80/0x80
[91476.313713] kthread+0x12f/0x150
[91476.313715] ? jbd2_journal_init_inode+0x120/0x120
[91476.313717] ? __kthread_bind_mask+0x70/0x70
[91476.313721] ret_from_fork+0x22/0x30
[91476.313728] INFO: task fio:1790564 blocked for more than 241 seconds.
[91476.318801] Not tainted 5.9.1-050901-generic #202010170731
[91476.323737] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91476.331077] task:fio state:D stack: 0 pid:1790564 ppid:1788387 flags:0x00000004
[91476.331081] Call Trace:
[91476.331088] __schedule+0x1fe/0x5e0
[91476.331091] schedule+0x55/0xc0
[91476.331094] io_schedule+0x45/0x70
[91476.331097] blk_mq_get_tag+0x11b/0x270
[91476.331102] ? wait_woken+0x80/0x80
[91476.331105] __blk_mq_alloc_request+0x82/0x120
[91476.331108] blk_mq_submit_bio+0x139/0x5f0
[91476.331111] __submit_bio_noacct+0x2ee/0x320
[91476.331113] submit_bio_noacct+0x4d/0x90
[91476.331116] submit_bio+0x4f/0x1b0
[91476.331119] iomap_dio_submit_bio+0x86/0x90
[91476.331121] iomap_dio_bio_actor+0x191/0x3d0
[91476.331123] iomap_dio_actor+0x2a/0x80
[91476.331124] iomap_apply+0x10c/0x340
[91476.331126] ? iomap_dio_rw+0x22a/0x4f0
[91476.331128] ? iomap_dio_inline_actor+0x130/0x130
[91476.331131] iomap_dio_rw+0x22a/0x4f0
[91476.331133] ? iomap_dio_inline_actor+0x130/0x130
[91476.331136] ext4_dio_write_iter+0x1c3/0x390
[91476.331139] ext4_file_write_iter+0x3f/0x50
[91476.331142] aio_write+0xf8/0x1b0
[91476.331146] ? do_shared_fault+0x6b/0xb0
[91476.331148] ? do_fault+0x1a5/0x1d0
[91476.331150] ? _cond_resched+0x1a/0x50
[91476.331152] ? io_submit_one+0x6b/0x390
[91476.331154] __io_submit_one.constprop.0+0x176/0x1f0
[91476.331155] io_submit_one+0xde/0x390
[91476.331158] __x64_sys_io_submit+0x86/0x170
[91476.331160] ? exit_to_user_mode_prepare+0x3b/0xd0
[91476.331163] ? irqentry_exit_to_user_mode+0x9/0x20
[91476.331165] do_syscall_64+0x38/0x90
[91476.331167] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[91476.331169] RIP: 0033:0x7f04a9d7c979
[91476.331171] Code: Bad RIP value.
[91476.331173] RSP: 002b:00007ffed3de11e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[91476.331177] RAX: ffffffffffffffda RBX: 00007f04a9c88af8 RCX: 00007f04a9d7c979
[91476.331178] RDX: 000000000063ceb0 RSI: 0000000000000001 RDI: 00007f045bdf9000
[91476.331181] RBP: 00007f045bdf9000 R08: 0000000000000000 R09: 0000000000000000
[91476.331182] R10: 000000000063d478 R11: 0000000000000246 R12: 0000000000000001
[91476.331183] R13: 0000000000000000 R14: 000000000063ceb0 R15: 000000000063cc50
[91671.367193] nvme nvme3: queue_size 128 > ctrl sqsize 64, clamping down
[91671.368638] nvme nvme3: creating 2 I/O queues.
[91671.383690] nvme nvme3: mapped 2/0/0 default/read/poll queues.
[91671.385009] nvme nvme3: new ctrl: NQN "nqn.2019-05.io.openebs:nexus-be70f20c-c4d7-415f-87d0-06f2e10430a6", addr 172.20.52.180:8420
[91671.744762] EXT4-fs (nvme3n1): mounted filesystem with ordered data mode. Opts: (null)
[91672.466871] IPv6: ADDRCONF(NETDEV_CHANGE): veth2010ee60: link becomes ready
[91672.469641] cbr0: port 3(veth2010ee60) entered blocking state
[91672.469644] cbr0: port 3(veth2010ee60) entered disabled state
[91672.472882] device veth2010ee60 entered promiscuous mode
[91672.473239] cbr0: port 3(veth2010ee60) entered blocking state
[91672.473242] cbr0: port 3(veth2010ee60) entered forwarding state
[101215.592815] cbr0: port 3(veth2010ee60) entered disabled state
[101215.608368] device veth2010ee60 left promiscuous mode
[101215.608373] cbr0: port 3(veth2010ee60) entered disabled stateroot@ip-172-20-52-180:~# cd /var/lib/kubelet/pods/ef86718d-13b6-4c29-8ac0-0eb5f639fd95/volumes/kubernetes.io~csi/pvc-83627c0a-20a2-4125-a698-0a4ba754a80f/mount
root@ip-172-20-52-180:/var/lib/kubelet/pods/ef86718d-13b6-4c29-8ac0-0eb5f639fd95/volumes/kubernetes.io~csi/pvc-83627c0a-20a2-4125-a698-0a4ba754a80f/mount# pwd
/var/lib/kubelet/pods/ef86718d-13b6-4c29-8ac0-0eb5f639fd95/volumes/kubernetes.io~csi/pvc-83627c0a-20a2-4125-a698-0a4ba754a80f/mount
root@ip-172-20-52-180:/var/lib/kubelet/pods/ef86718d-13b6-4c29-8ac0-0eb5f639fd95/volumes/kubernetes.io~csi/pvc-83627c0a-20a2-4125-a698-0a4ba754a80f/mount# ls
^C^C^C^C^CDescribe pv and pvc output:
[Macbook:~]$ kubectl describe pv
Name: pvc-83627c0a-20a2-4125-a698-0a4ba754a80f
Labels: <none>
Annotations: pv.kubernetes.io/provisioned-by: io.openebs.csi-mayastor
Finalizers: [kubernetes.io/pv-protection external-attacher/io-openebs-csi-mayastor]
StorageClass: mayastor-nvmf
Status: Bound
Claim: default/ms-volume-claim
Reclaim Policy: Delete
Access Modes: RWO
VolumeMode: Filesystem
Capacity: 6Gi
Node Affinity: <none>
Message:
Source:
Type: CSI (a Container Storage Interface (CSI) volume source)
Driver: io.openebs.csi-mayastor
VolumeHandle: 83627c0a-20a2-4125-a698-0a4ba754a80f
ReadOnly: false
VolumeAttributes: protocol=nvmf
repl=2
storage.kubernetes.io/csiProvisionerIdentity=1603369891716-8081-io.openebs.csi-mayastor
Events: <none>
Name: pvc-be70f20c-c4d7-415f-87d0-06f2e10430a6
Labels: <none>
Annotations: pv.kubernetes.io/provisioned-by: io.openebs.csi-mayastor
Finalizers: [kubernetes.io/pv-protection external-attacher/io-openebs-csi-mayastor]
StorageClass: mayastor-nvmf
Status: Bound
Claim: default/ms-volume-claim2
Reclaim Policy: Delete
Access Modes: RWO
VolumeMode: Filesystem
Capacity: 6Gi
Node Affinity: <none>
Message:
Source:
Type: CSI (a Container Storage Interface (CSI) volume source)
Driver: io.openebs.csi-mayastor
VolumeHandle: be70f20c-c4d7-415f-87d0-06f2e10430a6
ReadOnly: false
VolumeAttributes: protocol=nvmf
repl=2
storage.kubernetes.io/csiProvisionerIdentity=1603369891716-8081-io.openebs.csi-mayastor
Events: <none>
[Macbook:~]$ kubectl describe pvc
Name: ms-volume-claim
Namespace: default
StorageClass: mayastor-nvmf
Status: Bound
Volume: pvc-83627c0a-20a2-4125-a698-0a4ba754a80f
Labels: <none>
Annotations: kubectl.kubernetes.io/last-applied-configuration:
{"apiVersion":"v1","kind":"PersistentVolumeClaim","metadata":{"annotations":{},"name":"ms-volume-claim","namespace":"default"},"spec":{"ac...
pv.kubernetes.io/bind-completed: yes
pv.kubernetes.io/bound-by-controller: yes
volume.beta.kubernetes.io/storage-provisioner: io.openebs.csi-mayastor
Finalizers: [kubernetes.io/pvc-protection]
Capacity: 6Gi
Access Modes: RWO
VolumeMode: Filesystem
Mounted By: fio
Events: <none>
Name: ms-volume-claim2
Namespace: default
StorageClass: mayastor-nvmf
Status: Bound
Volume: pvc-be70f20c-c4d7-415f-87d0-06f2e10430a6
Labels: <none>
Annotations: kubectl.kubernetes.io/last-applied-configuration:
{"apiVersion":"v1","kind":"PersistentVolumeClaim","metadata":{"annotations":{},"name":"ms-volume-claim2","namespace":"default"},"spec":{"a...
pv.kubernetes.io/bind-completed: yes
pv.kubernetes.io/bound-by-controller: yes
volume.beta.kubernetes.io/storage-provisioner: io.openebs.csi-mayastor
Finalizers: [kubernetes.io/pvc-protection]
Capacity: 6Gi
Access Modes: RWO
VolumeMode: Filesystem
Mounted By: fio2
Events: <none>I have analyzed moac log file and reconstructed the following sequence of events.
First is created volume pvc-fbceb112-8f44-4004-94a8-8c6935218cd0 with size 8.5GB:
Then we create two more pools:
After 6 seconds we publish the first volume (at 12:31:46.853):
After 13s it is unpublished:
After 26 minutes it is destroyed:
Two questions so far:
Add 1. I suspect that the reason why it takes so long is data reset. We unmap/write zeros to all volume blocks. That raises another question of this could be done asynchronously after we reply that the volume has been destroyed. Is there any risk associated with this approach? k8s would hardly create a volume with the same UUID twice so at least that one can be ignored. What about free space reporting - we won't see the free space reclaimed until the async op finishes = nondeterministic - isn't that confusing?
Let's see what happens next.
Request to create another three volumes at once. All with size 5.3GB:
A concern: I can see all create volume requests proceeding in parallel. How can moac guarantee sufficient space on pool and load balancing fairness if it does not serialize volume create requests?
After 40 minutes the volume destruction begins (at 14:04:30.030):
Oct 22 14:05:46.609 error [csi]: CSI deleteVolume failed: Error: Unexpected error in deleteVolume method: TypeError: Cannot read property 'unregisterNexus' of null
at Nexus.unbind (/nix/store/9gybr2hl3nbv4fdddkvca40zylbrm39n-node_moac-0.1.0/lib/node_modules/moac/nexus.js:92:19)
at Nexus.destroy (/nix/store/9gybr2hl3nbv4fdddkvca40zylbrm39n-node_moac-0.1.0/lib/node_modules/moac/nexus.js:219:14)Again, the destruction of volumes took a couple of minutes, but eventually it completed. Looks easy but when looking at log file it is quite a mess because original requests are mixed with retries and delayed replies for the retries.
Final request is here. We create a volume with size 6.5GB:
nothing interesting is in moac's log after that. Further analysis of mayastor and csi logs will follow.
jkryl
commented
3 years ago I have analyzed other mayastor log files and haven't found anything interesting. Based on the log files it appears as if there were two mayastor volumes that are up and healthy (the same two volumes mentioned at the end of moac log analysis above). Nothing wrong or whatsoever. There isn't even an attempt to unpublish volumes and destroy them. That is something that one would expect when the pods are terminating.
So the only clue of something wrong is the error stack in kernel log and we would need to debug the issue at a system level as likely it will be related to NVME protocol as such. I see that the kernel version is recent enough (5.9) so we cannot say that it might be an old bug in nvme initiator implementation on linux.
ghost
commented
3 years ago You can reset the device suing the following command or one like it:
root@ip-172-20-52-180:/sys/class/nvme/nvme2/nvme2c2n1# echo 1 > device/reset_controller
root@ip-172-20-52-180:/sys/class/nvme/nvme2/nvme2c2n1# pwd
/sys/class/nvme/nvme2/nvme2c2n1@briankmatheson Let me summarize what we have discussed elsewhere.
The NVMe timeouts are set enormously high submitted IO that does not return will hang forever. This is a system configuration issue.
As the system is overload, the time it takes to serve any IO for mayastor is almost zero. That is to say if you start 10 jobs, which will spawn 10 processes, and you only have 2 CPUs, the disregarding system processed and kernel threads, we can not serve the IO at all.
Volumes destroyed that have IO's that have been submitted already -- will cause the system to wait for the IO until the end of time, this should be prevented by the finalizers which @blaisedias has validated to work correctly, did you by any chance had something do a --force?
So what can we do?
If we start with (1) the problem should not happen but 2,3,4 should for sure, always be considered.
jkryl
commented
3 years ago @gila Thanks for the summary.
IMO this ticket should aim to fix (3), that is "reduce insanely high timeout". Long timeout is the immediate root cause of fio pods stuck in terminating state. (2) and (4) are impossible to enforce as those are more recommendations for the users and falls into best practices category. (1) is something that we need but I would rather have a separate ticket for that and treat it as a new feature rather than a bug. So let's keep the ticket open and use it to deliver a fix for setting appropriate nvme timeout on its behalf.
jkryl
commented
3 years ago We have added the documentation on isolating cpu cores to mayastor gitbook. And we will be able to tweak io_timeout for nvmf targets when this PR is merged: https://github.com/openebs/Mayastor/pull/815 . The ticket will be closed when the PR is merged.
This happens on a cluster in aws set up by kops:
Looking at the log file there seems to be some kind of a problem with destroying the volumes used in the pods. More information about the resources in the cluster:
Stripped output of describe msv:
Log files will be attached.