action #129601
Updated by jlausuch 11 months ago
[installation/bootloader_uefi.pm](https://github.com/os-autoinst/os-autoinst-distri-opensuse/blob/master/tests/installation/bootloader_uefi.pm) times out quite often because openQA does not have time to enter uefi grub2 configuration screen before the 10s grub timeout. e.g. https://openqa.suse.de/tests/11157624#step/bootloader_uefi/11 https://openqa.suse.de/tests/11157620#step/bootloader_uefi/11 https://openqa.suse.de/tests/11157622#step/bootloader_uefi/11 The culprit is that the first `bootloader-grub2` takes too long to match. This is a successful run: ``` [2023-05-17T22:29:48.135632+02:00] [debug] [pid:78975] <<< testapi::assert_screen(mustmatch=[ "bootloader-shim-import-prompt", "bootloader-grub2" ], timeout=90) [2023-05-17T22:29:49.928958+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.82 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:29:49.929428+02:00] [debug] [pid:79369] no match: 89.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:29:50.104691+02:00] [debug] [pid:79369] no change: 88.0s [2023-05-17T22:29:50.588948+02:00] [debug] [pid:79369] no match: 88.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:29:51.105278+02:00] [debug] [pid:79369] no change: 87.0s [2023-05-17T22:29:51.589146+02:00] [debug] [pid:79369] no match: 87.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:29:52.105972+02:00] [debug] [pid:79369] no change: 86.0s [2023-05-17T22:29:52.589983+02:00] [debug] [pid:79369] no match: 86.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:00.232487+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.13 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:00.232953+02:00] [debug] [pid:79369] no match: 85.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:00.248237+02:00] [debug] [pid:79369] no change: 77.8s [2023-05-17T22:30:00.733227+02:00] [debug] [pid:79369] no match: 77.8s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:01.236512+02:00] [debug] [pid:79369] no change: 76.9s [2023-05-17T22:30:01.743323+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.51 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:01.743772+02:00] [debug] [pid:79369] no match: 76.9s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:09.594737+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.36 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:09.595227+02:00] [debug] [pid:79369] no match: 75.9s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:10.332028+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.71 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:10.332520+02:00] [debug] [pid:79369] no match: 68.5s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:11.328004+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.72 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:11.328472+02:00] [debug] [pid:79369] no match: 67.5s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:12.205373+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.59 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:12.205867+02:00] [debug] [pid:79369] no match: 66.5s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:19.704649+02:00] [warn] [pid:79369] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.09 seconds for 14 candidate needles - make your needles more specific [2023-05-17T22:30:19.705116+02:00] [debug] [pid:79369] no match: 65.5s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-17T22:30:20.417002+02:00] [debug] [pid:78975] >>> testapi::_handle_found_needle: found bootmenu-jeos-20201204, similarity 1.00 @ 101/208 [2023-05-17T22:30:20.419694+02:00] [debug] [pid:78975] tests/installation/bootloader_uefi.pm:124 called bootloader_setup::uefi_bootmenu_params -> lib/bootloader_setup.pm:383 called testapi::send_key_until_needlematch [2023-05-17T22:30:20.420160+02:00] [debug] [pid:78975] <<< testapi::check_screen(mustmatch="grub2-enter-edit-mode", timeout=0) ``` And this is a failed run: ``` [2023-05-18T22:31:23.112731+02:00] [debug] [pid:20579] <<< testapi::assert_screen(mustmatch=[ "bootloader-shim-import-prompt", "bootloader-grub2" ], timeout=90) [2023-05-18T22:31:24.904170+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.82 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:24.904637+02:00] [debug] [pid:21382] no match: 89.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:25.081871+02:00] [debug] [pid:21382] no change: 88.0s [2023-05-18T22:31:25.580143+02:00] [debug] [pid:21382] no match: 88.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:26.094924+02:00] [debug] [pid:21382] no change: 87.0s [2023-05-18T22:31:26.569793+02:00] [debug] [pid:21382] no match: 87.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:27.083393+02:00] [debug] [pid:21382] no change: 86.0s [2023-05-18T22:31:27.553981+02:00] [debug] [pid:21382] no match: 86.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:35.276260+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.19 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:35.276731+02:00] [debug] [pid:21382] no match: 85.0s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:36.083159+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.78 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:36.083646+02:00] [debug] [pid:21382] no match: 77.8s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:36.279755+02:00] [debug] [pid:21382] no change: 76.8s [2023-05-18T22:31:37.020384+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.74 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:37.020854+02:00] [debug] [pid:21382] no match: 76.8s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:44.628366+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.35 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:44.628834+02:00] [debug] [pid:21382] no match: 75.8s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:45.401250+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.74 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:45.401731+02:00] [debug] [pid:21382] no match: 68.4s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:46.386500+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.74 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:46.386994+02:00] [debug] [pid:21382] no match: 67.4s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:47.387270+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.74 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:47.387869+02:00] [debug] [pid:21382] no match: 66.4s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:55.130059+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 7.48 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:55.130529+02:00] [debug] [pid:21382] no match: 65.4s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:55.715449+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.56 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:55.715931+02:00] [debug] [pid:21382] no match: 57.9s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:31:56.143795+02:00] [debug] [pid:21382] no change: 56.9s [2023-05-18T22:31:56.669176+02:00] [warn] [pid:21382] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.52 seconds for 14 candidate needles - make your needles more specific [2023-05-18T22:31:56.669652+02:00] [debug] [pid:21382] no match: 56.9s, best candidate: bootloader_uefi-20210917 (0.00) [2023-05-18T22:32:04.606465+02:00] [debug] [pid:20579] >>> testapi::_handle_found_needle: found bootmenu-jeos-20201204, similarity 1.00 @ 101/208 [2023-05-18T22:32:04.610142+02:00] [debug] [pid:20579] tests/installation/bootloader_uefi.pm:124 called bootloader_setup::uefi_bootmenu_params -> lib/bootloader_setup.pm:383 called testapi::send_key_until_needlematch [2023-05-18T22:32:04.610684+02:00] [debug] [pid:20579] <<< testapi::check_screen(mustmatch="grub2-enter-edit-mode", timeout=0) ``` So, in the first case, the needle takes around 25s to be matched after the VM is started, but in the second case it takes ~45s, which makes the grub to pick the default option and boot the system without a chance to go to the `grub2-enter-edit-mode` screen.