Re: [PATCH v2 0/6] python/machine: use socketpair() for console socket

qemu-block

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [PATCH v2 0/6] python/machine: use socketpair() for console socket

From:	Peter Maydell
Subject:	Re: [PATCH v2 0/6] python/machine: use socketpair() for console socket
Date:	Thu, 27 Jul 2023 14:05:59 +0100

On Tue, 25 Jul 2023 at 19:04, John Snow <jsnow@redhat.com> wrote:
>
> Like we did for the QMP socket, use socketpair() for the console socket
> so that hopefully there isn't a race condition during early boot where
> data might get dropped on the floor.
>
> May or may not help with various race conditions where early console
> output is not showing up in the logs and/or potentially being missed by
> wait_for_console_pattern.
>

This seems to improve the test I was having trouble with on s390
(machine_aarch64_sbsaref.py:Aarch64SbsarefMachine.test_sbsaref_edk2_firmware)

However it still fails sometimes, apparently we get the first line
of output from the guest but lose a couple of subsequent lines.
Here's a failing log:

2023-07-27 12:55:29,870 protocol         L0481 DEBUG| Transitioning
from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
2023-07-27 12:55:29,930 __init__         L0153 DEBUG| NOTICE:  Booting
Trusted Firmware
2023-07-27 12:55:29,955 __init__         L0153 DEBUG| NOTICE:  BL1: Booting BL2
2023-07-27 12:55:29,955 __init__         L0153 DEBUG| NOTICE:  BL2:
v2.9(release):v2.9.0-51-gc0d8ee386
2023-07-27 12:55:29,955 __init__         L0153 DEBUG| NOTICE:  BL2:
Built : 16:44:16, May 30 2023
2023-07-27 12:55:30,092 __init__         L0153 DEBUG| NOTICE:  BL1: Booting BL31
2023-07-27 12:55:30,092 __init__         L0153 DEBUG| NOTICE:  BL31:
v2.9(release):v2.9.0-51-gc0d8ee386
2023-07-27 12:55:30,092 __init__         L0153 DEBUG| NOTICE:  BL31:
Built : 16:44:16, May 30 2023
2023-07-27 12:55:30,092 __init__         L0153 DEBUG| UEFI firmware
(version 1.0 built at 17:14:57 on Mar 21 2023)
2023-07-27 12:55:45,281 __init__         L0153 DEBUG|
ESC[2JESC[04DESC[=3hESC[2JESC[09DESC[2JESC[04DESC[0mESC[30mESC[40m
2023-07-27 12:55:45,538 __init__         L0153 DEBUG|
ESC[01;01HESC[0mESC[34mESC[47m
2023-07-27 12:55:45,642 __init__         L0153 DEBUG|
ESC[01;01HESC[02;02HQEMU SBSA-REF MachineESC[03;02Harm-virtESC[44C2.00
GHzESC[04;02H1.0ESC[49C1024 MB
RAMESC[05;02HESC[52CESC[06;02HESC[52CESC[0mESC[37mESC[40mESC[21;01H
2023-07-27 12:55:45,840 __init__         L0153 DEBUG|
ESC[21;01HESC[0mESC[30mESC[40mESC[25;53H  ESC[01D  ESC[01D  ESC[01D
ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D
 ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D  ESC[01D
ESC[01D  ESC[01D  ESC[0mESC[30mESC[47mESC[07;01H
2023-07-27 12:55:45,926 __init__         L0153 DEBUG| ESC[07;01H
2023-07-27 12:55:46,032 __init__         L0153 DEBUG|
ESC[0mESC[37mESC[40mESC[30C<Standard English>ESC[0mESC[30mESC[47m
   ESC[57D   Select Language            ESC[0mESC[34mESC[47mESC[09;01H

ESC[0mESC[30mESC[47mESC[10;01H   ESC[02D>ESC[01CDevice Manager
                               ESC[11;01H   ESC[02D>ESC[01CBoot
Manager                                          ESC[12;01H
ESC[02D>ESC[01CBoot Maintenance Manager
ESC[0mESC[34mESC[47mESC[13;01H
                ESC[0mESC[30mESC[47mESC[14;01H   Continue
                                ESC[15;01H   Reset
                            ESC[16;01H
                        ESC[17;01H
                    ESC[18;01H
                ESC[19;01H
            ESC[20;01H
2023-07-27 12:55:46,067 __init__         L0153 DEBUG|
ESC[0mESC[37mESC[40mESC[23;02H ESC[22;02H ESC[50C
   ESC[51D                          ESC[23;53H
  ESC[77D^v=Move Highlight       ESC[22;03H
ESC[23;27H<Enter>=Select Entry      ESC[0mESC[34mESC[47mESC[08;58HThis
is the option
2023-07-27 12:55:46,076 __init__         L0153 DEBUG| ESC[57Cone
adjusts to change
2023-07-27 12:55:46,076 __init__         L0153 DEBUG| ESC[57Cthe
language for the
2023-07-27 12:55:46,080 __init__         L0153 DEBUG| ESC[57Ccurrent system
2023-07-27 12:55:46,085 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,085 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,087 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,090 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,094 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,094 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,100 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:55:46,101 __init__         L0153 DEBUG| ESC[57C
2023-07-27 12:58:25,379 stacktrace       L0039 ERROR|
2023-07-27 12:58:25,380 stacktrace       L0041 ERROR| Reproduced
traceback from:
/home/linux1/qemu/build/aarch64/tests/venv/lib/python3.8/site-packages/avocado/core/test.py:770
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR| Traceback (most
recent call last):
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/home/linux1/qemu/build/aarch64/tests/venv/lib/python3.8/site-packages/avocado/core/decorators.py",
line 90, in wrapper
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|     return
function(obj, *args, **kwargs)
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/home/linux1/qemu/build/aarch64/tests/avocado/machine_aarch64_sbsaref.py",
line 96, in test_sbsaref_edk2_firmware
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|
wait_for_console_pattern(self, "BL1: v2.9(release):v2.9")
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/home/linux1/qemu/build/aarch64/tests/avocado/avocado_qemu/__init__.py",
line 199, in wait_for_console_pattern
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|
_console_interaction(test, success_message, failure_message, None,
vm=vm)
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/home/linux1/qemu/build/aarch64/tests/avocado/avocado_qemu/__init__.py",
line 148, in _console_interaction
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|     msg =
console.readline().decode().strip()
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/usr/lib/python3.8/socket.py", line 669, in readinto
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|     return
self._sock.recv_into(b)
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|   File
"/home/linux1/qemu/build/aarch64/tests/venv/lib/python3.8/site-packages/avocado/plugins/runner.py",
line 77, in sigterm_handler
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR|     raise
RuntimeError("Test interrupted by SIGTERM")
2023-07-27 12:58:25,381 stacktrace       L0045 ERROR| RuntimeError:
Test interrupted by SIGTERM

Compared to the output logs for a passing run, you can see that
although we captured the first line of output from the guest
("Booting Trusted Firmware") we missed lines 2 and 3 (the
BL1 version line and the BL1 Built: line).

2023-07-27 12:54:07,676 protocol         L0481 DEBUG| Transitioning
from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
2023-07-27 12:54:07,690 __init__         L0153 DEBUG| NOTICE:  Booting
Trusted Firmware
2023-07-27 12:54:07,691 __init__         L0153 DEBUG| NOTICE:  BL1:
v2.9(release):v2.9.0-51-gc0d8ee386
2023-07-27 12:54:07,691 __init__         L0153 DEBUG| BL1: Built :
16:44:16, May 30 2023
2023-07-27 12:54:07,754 __init__         L0153 DEBUG| NOTICE:  BL1: Booting BL2
2023-07-27 12:54:07,828 __init__         L0153 DEBUG| NOTICE:  BL2:
v2.9(release):v2.9.0-51-gc0d8ee386
2023-07-27 12:54:07,828 __init__         L0153 DEBUG| NOTICE:  BL2:
Built : 16:44:16, May 30 2023
2023-07-27 12:54:07,855 __init__         L0153 DEBUG| NOTICE:  BL1: Booting BL31
2023-07-27 12:54:07,877 __init__         L0153 DEBUG| NOTICE:  BL31:
v2.9(release):v2.9.0-51-gc0d8ee386
2023-07-27 12:54:07,883 __init__         L0153 DEBUG| NOTICE:  BL31:
Built : 16:44:16, May 30 2023
2023-07-27 12:54:07,891 __init__         L0153 DEBUG| UEFI firmware
(version 1.0 built at 17:14:57 on Mar 21 2023)
2023-07-27 12:54:18,354 __init__         L0153 DEBUG|
ESC[2JESC[04DESC[=3hESC[2JESC[09DESC[2JESC[04DESC[0mESC[30mESC[40m
2023-07-27 12:54:18,539 __init__         L0153 DEBUG|
ESC[01;01HESC[0mESC[34mESC[47m
2023-07-27 12:54:18,631 __init__         L0153 DEBUG|
ESC[01;01HESC[02;02HQEMU SBSA-REF MachineESC[03;02Harm-virtESC[44C2.00
GHzESC[04;02H1.0ESC[49C1024 MB
RAMESC[05;02HESC[52CESC[06;02HESC[52CESC[0mESC[37mESC[40mESC[21;01H
2023-07-27 12:54:18,639 machine          L0627 DEBUG| Shutting down VM
appliance; timeout=30
2023-07-27 12:54:18,639 machine          L0551 DEBUG| Attempting
graceful termination
2023-07-27 12:54:18,639 machine          L0518 DEBUG| Closing console socket
2023-07-27 12:54:18,640 machine          L0561 DEBUG| Politely asking
QEMU to terminate


thanks
-- PMM

[Prev in Thread]

Current Thread

[Next in Thread]

[PATCH v2 4/6] python/machine: use socketpair() for console connections, (continued)
- [PATCH v2 4/6] python/machine: use socketpair() for console connections, John Snow, 2023/07/25
  - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, Daniel P . Berrangé, 2023/07/25
  - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, Ani Sinha, 2023/07/26
    - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, John Snow, 2023/07/26
    - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, Ani Sinha, 2023/07/27
    - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, Ani Sinha, 2023/07/27
    - Re: [PATCH v2 4/6] python/machine: use socketpair() for console connections, Daniel P . Berrangé, 2023/07/27
- [PATCH v2 2/6] python/machine: close sock_pair in cleanup path, John Snow, 2023/07/25
  - Re: [PATCH v2 2/6] python/machine: close sock_pair in cleanup path, Daniel P . Berrangé, 2023/07/25
    - Re: [PATCH v2 2/6] python/machine: close sock_pair in cleanup path, Ani Sinha, 2023/07/26
- Re: [PATCH v2 0/6] python/machine: use socketpair() for console socket, Peter Maydell <=

Prev by Date: Re: [PATCH v2] block/file-posix: fix g_file_get_contents return path
Next by Date: Re: Lost partition tables on ide-hd + ahci drive
Previous by thread: Re: [PATCH v2 2/6] python/machine: close sock_pair in cleanup path
Next by thread: [PATCH v7 0/4] hw/ufs: Add Universal Flash Storage (UFS) support
Index(es):
- Date
- Thread