Bug 14912

Summary:	runqemu.RunqemuTests.test_boot_qemu_boot failure: I/O error, dev vda
Product:	[QA/Testing] Runtime Testing	Reporter:	Alexandre Belloni <alexandre.belloni>
Component:	oeqa/runtime	Assignee:	Richard Purdie <richard.purdie>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	High	CC:	alexandre.belloni, pavel, randy.macleod
Version:	unspecified
Target Milestone:	4.1 M3
Hardware:	x86
OS:	Multiple
Whiteboard:	AB-INT
OS type for building Yocto:	---	Type of Regression:	---
Verified:		Documentation change:	No (bug/feature does not impact docs)

Description Alexandre Belloni 2022-09-08 13:38:32 UTC

https://autobuilder.yoctoproject.org/typhoon/#/builders/127/builds/86/steps/14/logs/stdio

oe-selftest-armhost ubuntu1804-arm-1

[   12.668618] I/O error, dev vda, sector 32848 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.670319] I/O error, dev vda, sector 32850 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.672500] I/O error, dev vda, sector 32852 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.674144] I/O error, dev vda, sector 32854 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.675836] I/O error, dev vda, sector 32856 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.676572] I/O error, dev vda, sector 32858 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.677476] I/O error, dev vda, sector 32860 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.678836] I/O error, dev vda, sector 32862 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.679653] I/O error, dev vda, sector 32864 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.680587] I/O error, dev vda, sector 32866 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   12.707261] ------------[ cut here ]------------
[   12.708325] WARNING: CPU: 2 PID: 1 at block/blk-mq.c:1143 blk_mq_start_request+0xb0/0x110
[   12.709727] Modules linked in:
[   12.710757] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 5.19.3-yocto-standard #1
[   12.711770] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
[   12.713063] RIP: 0010:blk_mq_start_request+0xb0/0x110
[   12.714003] Code: 00 02 00 48 89 43 68 8b 43 2c c1 e8 09 66 89 43 70 49 8b 7c 24 28 48 85 ff 74 8b 48 89 de e8 e7 ff 00 00 8b 43 78 85 c0 74 83 <0f> 0b e9 7c ff ff ff 65 8b 05 52 68 03 67 89 c0 48 0f a3 05 70 20
[   12.715482] RSP: 0000:ffff8d97c0013780 EFLAGS: 00000202
[   12.716219] RAX: 0000000000000001 RBX: ffff8c2a02b17080 RCX: 0000000000000002
[   12.717023] RDX: ffff8c2a02b17180 RSI: ffff8c2a02b17080 RDI: ffff8c2a02b17080
[   12.717569] RBP: ffff8d97c0013790 R08: 0000000000000002 R09: ffff8c2a02b17180
[   12.718296] R10: ffff8c2a02b17180 R11: ffff8d97c00137f0 R12: ffff8c2a0189ecc0
[   12.719156] R13: 0000000000000000 R14: ffff8c2a02ab4800 R15: ffff8c2a029efc00
[   12.720046] FS:  0000000000000000(0000) GS:ffff8c2a0f900000(0000) knlGS:0000000000000000
[   12.721840] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   12.722325] CR2: 0000000000000000 CR3: 000000000c80a000 CR4: 00000000001506e0
[   12.724116] Call Trace:
[   12.725925]  <TASK>
[   12.727866]  virtio_queue_rq+0x60/0x200
[   12.728561]  __blk_mq_try_issue_directly+0x15f/0x1d0
[   12.729487]  blk_mq_plug_issue_direct.constprop.0+0x93/0x150
[   12.730529]  blk_mq_flush_plug_list+0x23f/0x2a0
[   12.731132]  __blk_flush_plug+0xe9/0x130
[   12.731493]  blk_finish_plug+0x2d/0x50
[   12.732230]  generic_writepages+0x89/0xb0
[   12.733282]  blkdev_writepages+0xe/0x20
[   12.733928]  do_writepages+0xd2/0x1d0
[   12.734270]  filemap_fdatawrite_wbc+0x6a/0x90
[   12.734857]  __filemap_fdatawrite_range+0x58/0x80
[   12.735280]  filemap_write_and_wait_range+0x2d/0x90
[   12.735947]  sync_blockdev+0x27/0x40
[   12.736265]  jbd2_journal_recover+0x116/0x130
[   12.737157]  jbd2_journal_load+0xd5/0x310
[   12.738081]  ext4_fill_super+0x2e04/0x3a70
[   12.738503]  ? idr_alloc_u32+0x81/0xe0
[   12.739385]  ? snprintf+0x51/0x70
[   12.739986]  get_tree_bdev+0x175/0x260
[   12.740324]  ? ext4_calculate_overhead+0x4d0/0x4d0
[   12.741316]  ext4_get_tree+0x15/0x20
[   12.742168]  vfs_get_tree+0x2a/0xc0
[   12.742468]  path_mount+0x301/0xb00
[   12.743234]  ? putname+0x57/0x70
[   12.743547]  init_mount+0x6e/0xa1
[   12.744111]  do_mount_root+0x92/0x11e
[   12.744437]  mount_block_root+0x107/0x217
[   12.745412]  mount_root+0x1fe/0x225
[   12.746187]  prepare_namespace+0x13f/0x174
[   12.746587]  kernel_init_freeable+0x20d/0x223
[   12.747340]  ? rest_init+0xc0/0xc0
[   12.748017]  kernel_init+0x1a/0x130
[   12.748369]  ret_from_fork+0x22/0x30
[   12.749565]  </TASK>
[   12.750325] ---[ end trace 0000000000000000 ]---
[   12.752200] Buffer I/O error on dev vda, logical block 1, lost async page write
[   12.754965] Buffer I/O error on dev vda, logical block 2, lost async page write
[   12.758413] Buffer I/O error on dev vda, logical block 221, lost async page write
[   12.760097] Buffer I/O error on dev vda, logical block 223, lost async page write
[   12.762078] Buffer I/O error on dev vda, logical block 407, lost async page write
[   12.763180] Buffer I/O error on dev vda, logical block 409, lost async page write
[   12.764118] Buffer I/O error on dev vda, logical block 410, lost async page write
[   12.765325] Buffer I/O error on dev vda, logical block 21994, lost async page write
[   12.774252] JBD2: recovery failed
[   12.775371] EXT4-fs (vda): error loading journal


At the same time, on the host:

[390203.761201] nfs: server 172.29.10.207 not responding, still trying
[390240.624923] nfs: server 172.29.10.207 not responding, timed out
[390420.655512] nfs: server 172.29.10.207 not responding, timed out
[390425.775473] nfs: server 172.29.10.207 not responding, timed out
[390600.686123] nfs: server 172.29.10.207 not responding, timed out
[390605.934082] nfs: server 172.29.10.207 not responding, timed out
[390612.334030] nfs: server 172.29.10.207 not responding, timed out
[390781.292752] nfs: server 172.29.10.207 not responding, timed out
[390786.156697] nfs: server 172.29.10.207 not responding, timed out
[390791.276658] nfs: server 172.29.10.207 not responding, timed out
[390797.484611] nfs: server 172.29.10.207 not responding, timed out
[390961.323504] nfs: server 172.29.10.207 not responding, timed out
[390971.499448] nfs: server 172.29.10.207 not responding, timed out
[...]
[393519.513245] nfs: server 172.29.10.207 not responding, timed out
[393525.337200] nfs: server 172.29.10.207 not responding, timed out
[393535.833130] nfs: server 172.29.10.207 not responding, timed out
[393546.073053] nfs: server 172.29.10.207 not responding, timed out
[393553.241339] nfs: server 172.29.10.207 OK

Comment 1 Alexandre Belloni 2022-09-08 14:12:41 UTC

https://autobuilder.yoctoproject.org/typhoon/#builders/110/builds/4720/steps/13/logs/stdio

Traceback (most recent call last):
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/runtime/cases/systemd.py", line 108, in test_systemd_status
    self.systemctl('status --full', 'avahi-daemon.service')
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/runtime/cases/systemd.py", line 25, in systemctl
    self.assertEqual(status, expected, message)
AssertionError: 3 != 0 : SYSTEMD_BUS_TIMEOUT=240s systemctl status --full avahi-daemon.service
○ avahi-daemon.service - Avahi mDNS/DNS-SD Stack
     Loaded: loaded (/lib/systemd/system/avahi-daemon.service; enabled; preset: enabled)
     Active: inactive (dead) since Thu 2022-09-08 01:57:24 UTC; 22min ago
   Duration: 46min 15.940s
TriggeredBy: ● avahi-daemon.socket
   Main PID: 240 (code=exited, status=0/SUCCESS)
     Status: "avahi-daemon 0.8 starting up."
Sep 08 01:11:05 qemuarm systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Sep 08 01:11:07 qemuarm systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Sep 08 01:57:23 qemuarm systemd[1]: avahi-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Sep 08 01:57:24 qemuarm systemd[1]: avahi-daemon.service: Deactivated successfully.
Test case systemd.SystemdServiceTests.test_systemd_disable_enable depends on systemd.SystemdServiceTests.test_systemd_status but it didn't pass/run.

On the host:

[389747.281880] nfs: server 172.29.10.207 not responding, timed out
[389928.101089] nfs: server 172.29.10.207 not responding, timed out
[389932.644953] nfs: server 172.29.10.207 not responding, timed out
[...]
[393075.920981] nfs: server 172.29.10.207 not responding, timed out
[393091.088599] nfs: server 172.29.10.207 not responding, timed out

Comment 2 Pavel Zhukov 2022-09-08 14:25:02 UTC

Same issue as in https://bugzilla.yoctoproject.org/show_bug.cgi?id=14787 ?

Comment 3 Randy MacLeod 2022-09-08 14:58:32 UTC

Potentially similar problem:
  https://gitlab.com/qemu-project/qemu/-/issues/649
we are going to update qemu to 7.1 to see how that goes.

Comment 4 Alexandre Belloni 2022-09-08 20:57:09 UTC

The NFS timeout may not be related

Comment 5 Richard Purdie 2022-09-09 15:43:11 UTC

Upgraded to qemu 7.1.0 which is our best hope for resolving this: https://git.yoctoproject.org/poky/commit/?id=9040d46f59643270695afdb093e8b403b89b898a