Bug 14181

Summary: Failure to unpickle during testimage
Product: [Build System, Metadata & Runtime] BitBake Reporter: Ross Burton <ross.burton>
Component: bitbakeAssignee: Richard Purdie <richard.purdie>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium+ CC: alexandre.belloni, jon.mason, poky.bs.watcher, poky.watcher, randy.macleod
Version: 3.3   
Target Milestone: 3.3 M3   
Hardware: x86   
OS: Multiple   
URL: https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/1800
Whiteboard: AB-INT
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)

Description Ross Burton 2021-01-11 11:44:32 UTC 
During testimage, an unpickle fails:

ERROR: failed load pickle ''utf-8' codec can't decode byte 0x80 in position 570: invalid start byte':

'b'\x80\x03clogging\nLogRecord\nq\x00)\x81q\x01}q\x02(X\x04\x00\x00\x00nameq\x03X\x07\x00\x00\x00BitBakeq\x04X\x03\x00\x00\x00msgq\x05X\x1c\x10\x00\x00Partial data from SSH call: ted\n[    2.979538] hdc: host max PIO4 wanted PIO255(auto-tune) selected PIO0\n[    2.329926] hdc: QEMU DVD-ROM, ATAPI CD/DVD-ROM drive\n[    1.642474] Probing IDE interface ide1...\n[    1.103041] Probing IDE interface ide0...\n[    1.103041]     ide1: BM-DMA at 0xc0e8-0xc0ef\n[    1.102581]     ide0: BM-DMA at 0xc0e0-0xc0e7\n[    1.098314] Report any missing HW support to linux-ide@vger.kernel.org\n[    1.098314] legacy IDE will be removed in 2021, please switch to libata\nStarting Connection service...\n[    1.098314] piix 0000:00:01.1:<event>\x80\x03clogging\nLogRecord\nq\x00)\x81q\x01}q\x02(X\x04\x00\x00\x00nameq\x03X\x07\x00\x00\x00BitBakeq\x04X\x03\x00\x00\x00msgq\x05X4\x00\x00\x00time: 1610164805.497182, endtime: 1610165105.4971802q\x06X\x04\x00\x00\x00argsq\x07)X\t\x00\x00\x00levelnameq\x08X\x05\x00\x00\x00DEBUGq\tX\x07\x00\x00\x00levelnoq\nK\nX\x08\x00\x00\x00pathnameq\x0bXN\x00\x00\x00/home/pokybuild/yocto-worker/qemux86-alt/build/meta/lib/oeqa/utils/__init__.pyq\x0cX\x08\x00\x00\x00filenameq\rX\x0b\x00\x00\x00__init__.pyq\x0eX\x06\x00\x00\x00moduleq\x0fX\x08\x00\x00\x00__init__q\x10X\x08\x00\x00\x00exc_infoq\x11NX\x08\x00\x00\x00exc_textq\x12NX\n\x00\x00\x00stack_infoq\x13NX\x06\x00\x00\x00linenoq\x14K>X\x08\x00\x00\x00funcNameq\x15X\x12\x00\x00\x00_bitbake_log_debugq\x16X\x07\x00\x00\x00createdq\x17GA\xd7\xfeJ\x91_\xd2?X\x05\x00\x00\x00msecsq\x18G@\x7f\x13Q\x86\x00\x00\x00X\x0f\x00\x00\x00relativeCreatedq\x19G@\xfe\xcd~\xd4 \x00\x00X\x06\x00\x00\x00threadq\x1a\x8a\x06\x80\xdb\x08\xf1"\x7fX\n\x00\x00\x00threadNameq\x1bX\n\x00\x00\x00MainThreadq\x1cX\x0b\x00\x00\x00processNameq\x1dX\x0b\x00\x00\x00MainProcessq\x1eX\x07\x00\x00\x00processq\x1fMv\xb8X\x07\x00\x00\x00taskpidq Mv\xb8ub.</event><event>\x80\x03clogging\nLogRecord\nq\x00)\x81q\x01}q\x02(X\x04\x00\x00\x00nameq\x03X\x07\x00\x00\x00BitBakeq\x04X\x03\x00\x00\x00msgq\x05X\x1c\x10\x00\x00Partial data from SSH call: cheduler mq-deadline registered\n[    0.831482] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)\n[    0.830446] Asymmetric key parser \'x509\' registered\n[    0.829490] Key type asymmetric registered\n[    0.823596] Key type cifs.idmap registered\n[    0.822608] Key type id_legacy registered\n[    0.821258] Key type id_resolver registered\n[    0.820189] NFS: Registering the id_resolver key type\n[    0.812456] workingset: timestamp_bits=14 max_order=17 bucket_order=3\n[    0.812456] Initialise system trusted keyrings\n[    0.812456] check: Scanning for low memory corruption every 60 seconds\n[    0.812456] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x257a34a6eea, max_idle_ns: 440795264358 ns\n[    0.811501] PCI: CLS 0 bytes, default 64\n[    0.809879] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]\n[    0.797548] pci 0000:00:01.2: quirk_usb_early_handoff+0x0/0x661 took 53224 usecs\n[    0.770849] PCI: setting IRQ 11 as level-triggered\n[    0.769040] PCI Interrupt Link [LNKD] enabled at IRQ 11\n[    0.741380] pci 0000:00:01.0: Activating ISA DMA hang workarounds\n[    0.740407] pci 0000:00:00.0: Limiting direct PCI/PCI transfers\n[    0.739173] pci 0000:00:01.0: PIIX3: Enabling Passive Release\n[    0.737773] RPC: Registered tcp NFSv4.1 backchannel transport module.\n[    0.734905] RPC: Registered tcp transport module.\n[    0.729980] RPC: Registered udp transport module.\n[    0.729980] RPC: Registered named UNIX socket transport module.\n[    0.729980] NET: Registered protocol family 1\n[    0.729980] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)\n[    0.729040] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)\n[    0.727756] TCP: Hash tables configured (established 4096 bind 4096)\n[    0.726382] TCP bind hash table entries: 4096 (order: 3, 32768 bytes, linear)\n[    0.724801] TCP established hash table entries: 4096 (order: 2, 16384 bytes, linear)\n[    0.719021] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)\n[    0.719021] NET: Registered protocol family 2\n[    0.719021] pci_bus 0000:00: resource 7 [mem 0x20000000-0xfebfffff window]\n[    0.719021] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]\n[    0.718032] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]\n[    0.716811] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]\n[    0.713726] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns\n[    0.677062] thermal_sys: Registered thermal governor \'user_space\'\n[    0.677062] thermal_sys: Registered thermal governor \'step_wise\'\n[    0.670743] pnp: PnP ACPI: found 7 devices\n[    0.670519] pnp 00:06: Plug and Play ACPI device, IDs PNP0b00 (active)\n[    0.670501] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active)\n[    0.670485] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)\n[    0.670465] pnp 00:03: Plug and Play ACPI device, IDs PNP0400 (active)\n[    0.670445] pnp 00:02: Plug and Play ACPI device, IDs PNP0700 (active)\n[    0.670428] pnp 00:02: [dma 2]\n[    0.670416] pnp 00:01: Plug and Play ACPI device, IDs PNP0f13 (active)\n[    0.670389] pnp 00:00: Plug and Play ACPI device, IDs PNP0303 (active)\n[    0.657130] pnp: PnP ACPI init\n[    0.565762] random: fast init done\n[    0.528728] clocksource: Switched to clocksource kvm-clock\n[    0.528728] Bluetooth: SCO socket layer initialized\n[    0.528728] Bluetooth: L2CAP socket layer initialized\n[    0.527747] Bluetooth: HCI socket layer initialized\n[    0.525733] Bluetooth: HCI device and connection manager initialized\n[    0.525544] NET: Registered protocol family 31\n[    0.524750] Bluetooth: Core ver 2.22\n[    0.523909] e820: reserve RAM buffer [mem 0x1ffdb000-0x1fffffff]\n[    0.523903] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]\n[    0.523741] PCI: pci_cache_line_size set to 64 bytes\n[    0.522925] PCI: Using ACPI for IRQ routing\n[    0.521728] PTP clock support registered\n[    0.521728] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>\n[    0.521728] pps_coq\x06X\x04\x00\x00\x00argsq\x07)X\t\x00\x00\x00levelnameq\x08X\x05\x00\x00\x00DEBUGq\tX\x07\x00\x00\x00levelnoq\nK\nX\x08\x00\x00\x00pathnameq\x0bXN\x00\x00\x00/home/pokybuild/yocto-worker/qemux86-alt/build/meta/lib/oeqa/utils/__init__.pyq\x0cX\x08\x00\x00\x00filenameq\rX\x0b\x00\x00\x00__init__.pyq\x0eX\x06\x00\x00\x00moduleq\x0fX\x08\x00\x00\x00__init__q\x10X\x08\x00\x00\x00exc_infoq\x11NX\x08\x00\x00\x00exc_textq\x12NX\n\x00\x00\x00stack_infoq\x13NX\x06\x00\x00\x00linenoq\x14K>X\x08\x00\x00\x00funcNameq\x15X\x12\x00\x00\x00_bitbake_log_debugq\x16X\x07\x00\x00\x00createdq\x17GA\xd7\xfeJ\x91_\xd4\xefX\x05\x00\x00\x00msecsq\x18G@\x7f\x15\xf1f\x00\x00\x00X\x0f\x00\x00\x00relativeCreatedq\x19G@\xfe\xcd\x81t\x00\x00\x00X\x06\x00\x00\x00threadq\x1a\x8a\x06\x80\xdb\x08\xf1"\x7fX\n\x00\x00\x00threadNameq\x1bX\n\x00\x00\x00MainThreadq\x1cX\x0b\x00\x00\x00processNameq\x1dX\x0b\x00\x00\x00MainProcessq\x1eX\x07\x00\x00\x00processq\x1fMv\xb8X\x07\x00\x00\x00taskpidq Mv\xb8ub.''
Comment 1 Richard Purdie 2021-01-13 23:49:37 UTC 
It looks like kernel dmesg logs containing "<event>" which is a magic string in the event piping within bitbake might be corrupting the IPC.
Comment 2 Alexandre Belloni 2021-01-29 16:47:18 UTC 
Happened again:
https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/1882/steps/13
Comment 3 Jon Mason 2021-01-30 18:02:44 UTC 
Seeing the issue in https://autobuilder.yoctoproject.org/typhoon/#/builders/95/builds/1574