Project

General

Profile

Actions
Copy link

action #95759

closed

[qe-core] test fails in first_boot

Added by mgrifalconi over 3 years ago. Updated over 3 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
mgrifalconi
Category:
Bugs in existing tests
Target version:
QA (public) - QE-Core: Ready
Start date:
2021-07-21
Due date:
% Done:

100%

Estimated time:
Difficulty:

Description

Observation

It seems to fail constantly since a couple of days, for timeout after logging in (after a reboot).
From direct VNC connection, I could see that login worked within ~30s after the password prompt but openqa reached the 60s timeout.

Workaround is to use Dev Mode and resume the test after timeout

[2021-07-21T06:08:42.710 UTC] [debug] <<< testapi::type_string(string="SECRET STRING", max_interval=100, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-07-21T06:08:44.374 UTC] [debug] tests/qa_automation/patch_and_reboot.pm:66 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1141 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:1022 called opensusebasetest::handle_displaymanager_login -> lib/opensusebasetest.pm:847 called x11utils::handle_login -> lib/x11utils.pm:225 called testapi::send_key
[2021-07-21T06:08:44.375 UTC] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-07-21T06:08:44.745 UTC] [debug] tests/qa_automation/patch_and_reboot.pm:66 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1141 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:1022 called opensusebasetest::handle_displaymanager_login -> lib/opensusebasetest.pm:847 called x11utils::handle_login -> lib/x11utils.pm:226 called testapi::assert_screen
[2021-07-21T06:08:44.745 UTC] [debug] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "gnome-activities",
    "opensuse-welcome"
  ], timeout=60)
[2021-07-21T06:08:50.409 UTC] [debug] WARNING: check_asserted_screen took 5.66 seconds for 53 candidate needles - make your needles more specific
[2021-07-21T06:08:50.409 UTC] [debug] no match: 59.9s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-21T06:08:54.714 UTC] [debug] WARNING: check_asserted_screen took 4.28 seconds for 53 candidate needles - make your needles more specific
[2021-07-21T06:08:54.715 UTC] [debug] no match: 54.3s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-21T06:08:54.716 UTC] [debug] led state 0 1 1 -261
[2021-07-21T06:08:54.716 UTC] [debug] led state 2 1 1 -261
[2021-07-21T06:09:48.973 UTC] [debug] WARNING: check_asserted_screen took 54.23 seconds for 53 candidate needles - make your needles more specific
[2021-07-21T06:09:48.974 UTC] [debug] no match: 50.0s, best candidate: GNOME-workaround-bsc978076-20160504 (0.00)
[2021-07-21T06:09:48.992 UTC] [warn] !!! (eval): There is some problem with your environment, we detected a stall for 54.258465051651 seconds
[2021-07-21T06:10:06.577 UTC] [debug] WARNING: check_asserted_screen took 17.57 seconds for 53 candidate needles - make your needles more specific
[2021-07-21T06:10:06.577 UTC] [debug] no match: -4.3s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-21T06:10:07.131 UTC] [debug] >>> testapi::_check_backend_response: match=generic-desktop,gnome-activities,opensuse-welcome timed out after 60 (assert_screen)
[2021-07-21T06:10:07.278 UTC] [debug] isotovideo: pausing test execution on timeout as requested at qa_automation-patch_and_reboot

openQA test in scenario sle-15-SP3-Server-DVD-Updates-aarch64-qam-gnome@aarch64-virtio fails in
first_boot

Test suite description

Reproducible

Fails since (at least) Build 20210720-1

Expected result

Last good: 20210719-2 (or more recent)

Further details

Always latest result in this scenario: latest

Actions
Copy link
 #1

Updated by mgrifalconi over 3 years ago

This is likely affected as well https://openqa.suse.de/tests/6495146#
https://openqa.suse.de/tests/6505583#step/install_patterns/32

EDIT: copy/paste mess, sorry, I mean other osd jobs

Actions
Copy link
 #2

Updated by okurz over 3 years ago

mgrifalconi wrote:

This is likely affected as well https://progress.opensuse.org/issues/95759

you are linking the current ticket. Also, in redmine better just reference by #<id> for links with preview of the status and title.

Actions
Copy link
 #3

Updated by okurz over 3 years ago

what you can do is use https://progress.opensuse.org/projects/openqatests/wiki/Wiki#Statistical-investigation together with worker pinning and bisecting against the "last good" to identify what could be the root cause

Actions
Copy link
 #4

Updated by mgrifalconi over 3 years ago

It feels quite strange that a run was successful with 121 needles to sort out, but now fails with 53.

Successful: https://openqa.suse.de/tests/6482967/logfile?filename=autoinst-log.txt

[2021-07-19T14:37:29.940 CEST] [debug] tests/installation/first_boot.pm:25 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:1046 called testapi::check_screen
[2021-07-19T14:37:29.941 CEST] [debug] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "displaymanager",
    "guest-disable-display",
    "authentication-required-user-settings"
  ], timeout=30)
[2021-07-19T14:37:40.801 CEST] [debug] WARNING: check_asserted_screen took 10.86 seconds for 121 candidate needles - make your needles more specific
[2021-07-19T14:37:40.801 CEST] [debug] no match: 29.9s, best candidate: displaymanager-sles4sap-nousers-20200930 (0.86)
[2021-07-19T14:37:40.805 CEST] [warn] !!! (eval): There is some problem with your environment, we detected a stall for 11.0128071308136 seconds
[2021-07-19T14:37:48.810 CEST] [debug] WARNING: check_asserted_screen took 7.98 seconds for 121 candidate needles - make your needles more specific
[2021-07-19T14:37:48.811 CEST] [debug] no match: 19.1s, best candidate: displaymanager-sles4sap-nousers-20200930 (0.86)
[2021-07-19T14:37:58.421 CEST] [debug] WARNING: check_asserted_screen took 9.57 seconds for 121 candidate needles - make your needles more specific
[2021-07-19T14:37:58.421 CEST] [debug] no match: 11.0s, best candidate: GNOME-workaround-bsc978076-20160504 (0.00)
[2021-07-19T14:38:06.011 CEST] [debug] WARNING: check_asserted_screen took 7.54 seconds for 121 candidate needles - make your needles more specific
[2021-07-19T14:38:06.012 CEST] [debug] no match: 1.4s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-19T14:38:58.670 CEST] [debug] >>> testapi::_handle_found_needle: found boot_to_desktop-generic-desktop-20210119, similarity 1.00 @ 0/0

Failing: https://openqa.suse.de/tests/6489174/logfile?filename=autoinst-log.txt

[2021-07-20T02:27:18.531 CEST] [debug] tests/installation/first_boot.pm:25 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:1022 called opensusebasetest::handle_displaymanager_login -> lib/opensusebasetest.pm:847 called x11utils::handle_login -> lib/x11utils.pm:226 called testapi::assert_screen
[2021-07-20T02:27:18.531 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "gnome-activities",
    "opensuse-welcome"
  ], timeout=60)
[2021-07-20T02:27:25.439 CEST] [debug] WARNING: check_asserted_screen took 6.90 seconds for 53 candidate needles - make your needles more specific
[2021-07-20T02:27:25.439 CEST] [debug] no match: 59.9s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-20T02:27:31.069 CEST] [debug] WARNING: check_asserted_screen took 5.60 seconds for 53 candidate needles - make your needles more specific
[2021-07-20T02:27:31.070 CEST] [debug] no match: 53.0s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-20T02:27:37.296 CEST] [debug] WARNING: check_asserted_screen took 6.19 seconds for 53 candidate needles - make your needles more specific
[2021-07-20T02:27:37.296 CEST] [debug] no match: 47.4s, best candidate: GNOME-workaround-bsc978076-20160504 (0.00)
[2021-07-20T02:27:37.319 CEST] [debug] no change: 41.2s
[2021-07-20T02:28:39.906 CEST] [debug] WARNING: check_asserted_screen took 61.61 seconds for 53 candidate needles - make your needles more specific
[2021-07-20T02:28:39.907 CEST] [debug] no match: 40.2s, best candidate: GNOME-workaround-bsc978076-20160504 (0.00)
[2021-07-20T02:28:39.927 CEST] [warn] !!! (eval): There is some problem with your environment, we detected a stall for 62.1093330383301 seconds
[2021-07-20T02:29:02.993 CEST] [debug] WARNING: check_asserted_screen took 23.04 seconds for 53 candidate needles - make your needles more specific
[2021-07-20T02:29:02.993 CEST] [debug] no match: -21.5s, best candidate: firefox_nss-generic-desktop-20201224 (0.48)
[2021-07-20T02:29:03.650 CEST] [debug] >>> testapi::_check_backend_response: match=generic-desktop,gnome-activities,opensuse-welcome timed out after 60 (assert_screen)
Actions
Copy link
 #5

Updated by mgrifalconi over 3 years ago

Jozef cleaned up some needles and timeout is now increased https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/12944

Issue is not happening anymore

Actions
Copy link
 #6

Updated by mgrifalconi over 3 years ago

  • Status changed from New to Resolved
  • % Done changed from 0 to 100
Actions
Copy link
 #7

Updated by szarate over 3 years ago

  • Target version set to QE-Core: Ready
Actions
Copy link

Also available in: Atom PDF