QA » openQA Project » openQA Tests

From journal I can't see any failure.

Dec 11 05:53:22 susetest dbus-daemon[987]: [system] Activating service name='org.opensuse.Snapper' requested by ':1.120' (uid=0 pid=3513 comm="snapper list ") (using servicehelper)
Dec 11 05:53:22 susetest dbus-daemon[987]: [system] Successfully activated service 'org.opensuse.Snapper'
Dec 11 05:54:32 susetest wickedd-dhcp6[991]: br0: DHCPv6 is disabled by IPv6 router RA
Dec 11 05:54:32 susetest wickedd-dhcp6[991]: br0: DHCPv6 is disabled by IPv6 router RA
Dec 11 05:54:44 susetest gdm[2043]: GdmLocalDisplayFactory: received VT change event
Dec 11 05:54:44 susetest gdm[2043]: GdmLocalDisplayFactory: VT changed from 6 to 5
Dec 11 05:54:44 susetest gdm[2043]: GdmLocalDisplayFactory: VT of login window is 7
Dec 11 05:54:44 susetest gdm[2043]: GdmLocalDisplayFactory: VT not switched from login window
Dec 11 05:54:44 susetest gdm[2043]: GdmLocalDisplayFactory: active VT is not initial VT, so ignoring
Dec 11 05:54:44 susetest systemd[1]: Started Getty on tty5.
Dec 11 05:54:45 susetest gdm-password][2523]: accountsservice: ActUserManager: sending user-changed signal for user bernhard
Dec 11 05:54:45 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: sending user-changed signal for user gdm
Dec 11 05:54:45 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: sent user-changed signal for user gdm
Dec 11 05:54:45 susetest gdm-password][2523]: accountsservice: ActUserManager: sent user-changed signal for user bernhard
Dec 11 05:54:45 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: updating user gdm
Dec 11 05:54:45 susetest gdm-password][2523]: accountsservice: ActUserManager: updating user bernhard
Dec 11 05:54:53 susetest systemd-logind[1031]: New session 4 of user root.
Dec 11 05:54:53 susetest systemd[1]: Started Session 4 of user root.
Dec 11 05:54:53 susetest login[3696]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Dec 11 05:54:53 susetest login[3696]: ROOT LOGIN ON tty5
Dec 11 05:54:54 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: sending user-changed signal for user gdm
Dec 11 05:54:54 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: sent user-changed signal for user gdm
Dec 11 05:54:54 susetest gdm-launch-environment][2067]: accountsservice: ActUserManager: updating user gdm
Dec 11 05:54:54 susetest gdm-password][2523]: accountsservice: ActUserManager: sending user-changed signal for user bernhard
Dec 11 05:54:54 susetest gdm-password][2523]: accountsservice: ActUserManager: sent user-changed signal for user bernhard
Dec 11 05:54:54 susetest gdm-password][2523]: accountsservice: ActUserManager: updating user bernhard
Dec 11 05:55:01 susetest CRON[3752]: (root) CMD ([ -x /usr/lib64/sa/sa2 ] && exec /usr/lib64/sa/sa2 -A)
Dec 11 05:55:10 susetest kernel: sysrq: Show Blocked State
Dec 11 05:55:10 susetest kernel: task PC stack pid father
Dec 11 05:55:10 susetest kernel: kworker/u4:6 D 0 3193 2 0x00000028
Dec 11 05:55:10 susetest kernel: Workqueue: btrfs-qgroup-rescan btrfs_qgroup_rescan_helper [btrfs]
Dec 11 05:55:10 susetest kernel: Call trace:
Dec 11 05:55:10 susetest kernel: __switch_to+0xc4/0x220
Dec 11 05:55:10 susetest kernel: __schedule+0x2b8/0x740
Dec 11 05:55:10 susetest kernel: schedule+0x38/0xa8
Dec 11 05:55:10 susetest kernel: io_schedule+0x20/0x40
Dec 11 05:55:10 susetest kernel: wait_on_page_bit+0x194/0x270
Dec 11 05:55:10 susetest kernel: read_extent_buffer_pages+0x2d4/0x3f8 [btrfs]
Dec 11 05:55:10 susetest kernel: btree_read_extent_buffer_pages+0xac/0x168 [btrfs]
Dec 11 05:55:10 susetest kernel: read_tree_block+0x58/0x88 [btrfs]
Dec 11 05:55:10 susetest kernel: read_block_for_search.isra.13+0x1d0/0x388 [btrfs]
Dec 11 05:55:10 susetest kernel: btrfs_search_slot+0x354/0x978 [btrfs]
Dec 11 05:55:10 susetest kernel: btrfs_search_old_slot+0x178/0x800 [btrfs]
Dec 11 05:55:10 susetest kernel: 0xffff80003917c000
Dec 11 05:55:10 susetest kernel: 0x773417955edc0200
Dec 11 05:55:10 susetest kernel: 0x2
Dec 11 05:55:12 susetest kernel: BTRFS info (device vda2): qgroup scan completed (inconsistency flag cleared)

Maybe we can add more time out value.

I will add TIMEOUT_SCALE=3 to see the test results: https://openqa.suse.de/tests/3714286

We can workaround this issue by set TIMEOUT_SCALE=3. Verified on OSD and updated the test suite.
https://openqa.suse.de/tests/3714286#step/upgrade_snapshots/2

Reopen as https://openqa.nue.suse.com/tests/3853723#

I have re-run these three cases with timeout_scale=3 and this issue gone.

http://openqa.nue.suse.com/tests/3860172

[2020-02-04T09:37:33.690 UTC] [debug] <<< testapi::script_run(cmd="snapper list | tee /dev/ttyAMA0", output="", quiet=undef, timeout=0)
[2020-02-04T09:37:33.691 UTC] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:26 called testapi::script_run
[2020-02-04T09:37:33.691 UTC] [debug] <<< testapi::type_string(string="snapper list | tee /dev/ttyAMA0", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-02-04T09:37:34.840 UTC] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:26 called testapi::script_run
[2020-02-04T09:37:34.841 UTC] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2020-02-04T09:37:35.113 UTC] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:28 called testapi::wait_serial
[2020-02-04T09:37:35.113 UTC] [debug] <<< testapi::wait_serial(timeout=240, quiet=undef, record_output=undef, no_regex=0, buffer_size=undef, regexp="pre\s*(\|[^{|]){4,}\s\|\s*number\s*\|\s*before} (update|online migration)\s*\|\s*important=yes", expect_not_found=0)
[2020-02-04T09:39:55.674 UTC] [debug] >>> testapi::wait_serial: pre\s*(|[^{|]){4,}\s|\s*number\s*|\s*before} (update|online migration)\s*|\s*important=yes: ok

use time: 140s

http://openqa.nue.suse.com/tests/3860173
http://openqa.nue.suse.com/tests/3860174

[2020-02-04T10:25:10.165 CET] [debug] <<< testapi::script_run(cmd="snapper list | tee /dev/ttysclp0", quiet=undef, timeout=0, output="")
[2020-02-04T10:25:10.165 CET] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:26 called testapi::script_run
[2020-02-04T10:25:10.165 CET] [debug] <<< testapi::type_string(string="snapper list | tee /dev/ttysclp0", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-02-04T10:25:11.269 CET] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:26 called testapi::script_run
[2020-02-04T10:25:11.269 CET] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[ 513.232366] dbus-daemon[984]: [system] Activating service name='org.opensuse.Snapper' requested by ':1.108' (uid=0 pid=12228 comm="snapper list ") (using servicehelper)
[ 513.242755] dbus-daemon[984]: [system] Successfully activated service 'org.opensuse.Snapper'
[2020-02-04T10:25:11.537 CET] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/upgrade_snapshots.pm:28 called testapi::wait_serial
[2020-02-04T10:25:11.538 CET] [debug] <<< testapi::wait_serial(expect_not_found=0, buffer_size=undef, no_regex=0, record_output=undef, regexp="pre\s*(\|[^{|]){4,}\s\|\s*number\s*\|\s*before} (update|online migration)\s*\|\s*important=yes", timeout=240, quiet=undef)
# | Type | Pre # | Date | User | Used Space | Cleanup | Description | Userdata

----+--------+-------+---------------------------------+------+------------+---------+-----------------------+--------------
0 | single | | | root | | | current |

1* | single | | Tue 26 Nov 2019 04:58:54 AM EST | root | 157.75 MiB | | first root filesystem |

2 | single | | Tue 26 Nov 2019 05:08:24 AM EST | root | 17.38 MiB | number | after installation | important=yes
3 | pre | | Tue 26 Nov 2019 05:17:46 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
4 | post | 3 | Tue 26 Nov 2019 05:17:46 AM EST | root | 188.00 KiB | number | | important=no
5 | pre | | Tue 26 Nov 2019 05:17:53 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
6 | post | 5 | Tue 26 Nov 2019 05:17:54 AM EST | root | 192.00 KiB | number | | important=no
7 | pre | | Tue 26 Nov 2019 05:17:58 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
8 | post | 7 | Tue 26 Nov 2019 05:17:58 AM EST | root | 180.00 KiB | number | | important=no
9 | pre | | Tue 26 Nov 2019 05:18:03 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
10 | post | 9 | Tue 26 Nov 2019 05:18:03 AM EST | root | 220.00 KiB | number | | important=no
11 | pre | | Tue 04 Feb 2020 03:27:07 AM EST | root | 192.00 KiB | number | zypp(zypper) | important=no
12 | post | 11 | Tue 04 Feb 2020 03:27:08 AM EST | root | 208.00 KiB | number | | important=no
13 | pre | | Tue 04 Feb 2020 03:27:24 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
14 | post | 13 | Tue 04 Feb 2020 03:27:26 AM EST | root | 196.00 KiB | number | | important=no
15 | pre | | Tue 04 Feb 2020 03:27:48 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
16 | post | 15 | Tue 04 Feb 2020 03:27:50 AM EST | root | 184.00 KiB | number | | important=no
17 | pre | | Tue 04 Feb 2020 03:29:14 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
18 | post | 17 | Tue 04 Feb 2020 03:29:15 AM EST | root | 200.00 KiB | number | | important=no
19 | pre | | Tue 04 Feb 2020 03:29:36 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
20 | post | 19 | Tue 04 Feb 2020 03:29:37 AM EST | root | 204.00 KiB | number | | important=no
21 | pre | | Tue 04 Feb 2020 03:29:57 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
22 | post | 21 | Tue 04 Feb 2020 03:29:58 AM EST | root | 192.00 KiB | number | | important=no
23 | pre | | Tue 04 Feb 2020 03:30:19 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
24 | post | 23 | Tue 04 Feb 2020 03:30:31 AM EST | root | 184.00 KiB | number | | important=no
25 | pre | | Tue 04 Feb 2020 03:30:57 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
26 | post | 25 | Tue 04 Feb 2020 03:31:02 AM EST | root | 188.00 KiB | number | | important=no
27 | pre | | Tue 04 Feb 2020 03:31:24 AM EST | root | 96.00 KiB | number | zypp(zypper) | important=no
28 | post | 27 | Tue 04 Feb 2020 03:32:08 AM EST | root | 2.10 MiB | number | | important=no
29 | pre | | Tue 04 Feb 2020 03:32:19 AM EST | root | 420.00 KiB | number | zypp(zypper) | important=yes
30 | post | 29 | Tue 04 Feb 2020 03:45:55 AM EST | root | 58.84 MiB | number | | important=yes
31 | pre | | Tue 04 Feb 2020 03:48:40 AM EST | root | 112.00 KiB | number | zypp(zypper) | important=no
32 | post | 31 | Tue 04 Feb 2020 03:48:43 AM EST | root | 184.00 KiB | number | | important=no
33 | pre | | Tue 04 Feb 2020 03:49:04 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
34 | post | 33 | Tue 04 Feb 2020 03:49:06 AM EST | root | 208.00 KiB | number | | important=no
35 | pre | | Tue 04 Feb 2020 03:49:12 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
36 | post | 35 | Tue 04 Feb 2020 03:49:14 AM EST | root | 196.00 KiB | number | | important=no
37 | pre | | Tue 04 Feb 2020 03:49:20 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
38 | post | 37 | Tue 04 Feb 2020 03:49:22 AM EST | root | 180.00 KiB | number | | important=no
39 | pre | | Tue 04 Feb 2020 03:49:27 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
40 | post | 39 | Tue 04 Feb 2020 03:49:29 AM EST | root | 200.00 KiB | number | | important=no
41 | pre | | Tue 04 Feb 2020 03:49:35 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
42 | post | 41 | Tue 04 Feb 2020 03:49:38 AM EST | root | 204.00 KiB | number | | important=no
43 | pre | | Tue 04 Feb 2020 03:49:43 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
44 | post | 43 | Tue 04 Feb 2020 03:49:45 AM EST | root | 220.00 KiB | number | | important=no
45 | pre | | Tue 04 Feb 2020 03:49:51 AM EST | root | 128.00 KiB | number | zypp(zypper) | important=no
46 | post | 45 | Tue 04 Feb 2020 03:49:53 AM EST | root | 204.00 KiB | number | | important=no
47 | pre | | Tue 04 Feb 2020 03:54:11 AM EST | root | 1.27 MiB | number | before update | important=yes
48 | post | 47 | Tue 04 Feb 2020 04:15:10 AM EST | root | 3.41 MiB | number | after update | important=yes
49 | pre | | Tue 04 Feb 2020 04:17:24 AM EST | root | 1.17 MiB | number | zypp(zypper) | important=yes
50 | post | 49 | Tue 04 Feb 2020 04:19:28 AM EST | root | 41.16 MiB | number | | important=yes
[2020-02-04T10:26:44.639 CET] [debug] >>> testapi::wait_serial: pre\s*(|[^{|]){4,}\s|\s*number\s*|\s*before} (update|online migration)\s*|\s*important=yes: ok

used time: 93s

PR merged. https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/9508

Verify log : http://openqa.nue.suse.com/tests/3863093

Reproduce at https://openqa.nue.suse.com/tests/4081864#step/upgrade_snapshots/2

Clone with timeout_scale=3, wait http://openqa.nue.suse.com/tests/4084034.

In the log, snapper list returns in 20+s. I think the failed case reproduced the issue for openQA run tests in parallel cause VM very slow.
http://openqa.nue.suse.com/tests/4084034#