action #70876
Updated by okurz over 3 years ago
### observation Not sure why this job incompleted: ``` [37m[2020-09-02T00:15:10.754 CEST] [debug] Current version is 4.6.1598623827.924c995d [interface v20] [0m[37m[2020-09-02T00:15:10.840 CEST] [debug] git hash in /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse: ab7782333c508e136760d4299a0c32297a5c38fc [0m[37m[2020-09-02T00:15:11.276 CEST] [debug] usingenv DESKTOP=kde … [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv USBBOOT=1 [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv DISTRI=opensuse [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv QEMUCPU=host [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv INSTLANG=en_US [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv UEFI=1 [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv DVD=1 [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv KDE=1 [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv ISO=/var/lib/openqa/pool/3/openSUSE-Jump-15.2-DVD-aarch64-Build72.2-Media.iso [0m[37m[2020-09-02T00:15:11.277 CEST] [debug] usingenv ISO_MAXSIZE=4700372992 [0m[37m[2020-09-02T00:15:11.278 CEST] [debug] usingenv NOIMAGES=1 [0m[37m[2020-09-02T00:15:11.294 CEST] [debug] scheduling isosize tests/installation/isosize.pm … [0m[37m[2020-09-02T00:15:11.323 CEST] [debug] scheduling bootloader_uefi tests/installation/bootloader_uefi.pm [0m[37m[2020-09-02T00:15:11.327 CEST] [debug] scheduling welcome tests/installation/welcome.pm [0m[37m[2020-09-02T00:15:11.329 CEST] [debug] scheduling online_repos tests/installation/online_repos.pm [0m[37m[2020-09-02T00:15:11.330 CEST] [debug] scheduling installation_mode tests/installation/installation_mode.pm [0m[37m[2020-09-02T00:15:11.331 CEST] [debug] scheduling logpackages tests/installation/logpackages.pm [0m[37m[2020-09-02T00:15:11.333 CEST] [debug] scheduling system_role tests/installation/system_role.pm [0m[37m[2020-09-02T00:15:11.340 CEST] [debug] scheduling partitioning tests/installation/partitioning.pm [0m[37m[2020-09-02T00:15:11.341 CEST] [debug] scheduling partitioning_finish tests/installation/partitioning_finish.pm [0m[37m[2020-09-02T00:15:11.342 CEST] [debug] scheduling installer_timezone tests/installation/installer_timezone.pm [0m[37m[2020-09-02T00:15:11.344 CEST] [debug] scheduling user_settings tests/installation/user_settings.pm [0m[37m[2020-09-02T00:15:11.345 CEST] [debug] scheduling resolve_dependency_issues tests/installation/resolve_dependency_issues.pm [0m[37m[2020-09-02T00:15:11.363 CEST] [debug] scheduling installation_overview tests/installation/installation_overview.pm [0m[37m[2020-09-02T00:15:11.365 CEST] [debug] scheduling disable_grub_timeout tests/installation/disable_grub_timeout.pm [0m[37m[2020-09-02T00:15:11.367 CEST] [debug] scheduling start_install tests/installation/start_install.pm [0m[37m[2020-09-02T00:15:11.370 CEST] [debug] scheduling await_install tests/installation/await_install.pm [0m[37m[2020-09-02T00:15:11.371 CEST] [debug] scheduling logs_from_installation_system tests/installation/logs_from_installation_system.pm [0m[37m[2020-09-02T00:15:11.373 CEST] [debug] scheduling reboot_after_installation tests/installation/reboot_after_installation.pm [0m[37m[2020-09-02T00:15:11.375 CEST] [debug] scheduling grub_test tests/installation/grub_test.pm [0m[37m[2020-09-02T00:15:11.376 CEST] [debug] scheduling first_boot tests/installation/first_boot.pm [0m[37m[2020-09-02T00:15:11.377 CEST] [debug] scheduling system_workarounds tests/installation/system_workarounds.pm [0m[37m[2020-09-02T00:15:11.385 CEST] [debug] scheduling system_prepare tests/console/system_prepare.pm [0m[37m[2020-09-02T00:15:11.387 CEST] [debug] scheduling zypper_clear_repos tests/update/zypper_clear_repos.pm [0m[37m[2020-09-02T00:15:11.388 CEST] [debug] scheduling zypper_ar tests/console/zypper_ar.pm [0m[37m[2020-09-02T00:15:11.389 CEST] [debug] scheduling zypper_ref tests/console/zypper_ref.pm [0m[37m[2020-09-02T00:15:11.390 CEST] [debug] scheduling prepare_system_for_update_tests tests/update/prepare_system_for_update_tests.pm [0m[37m[2020-09-02T00:15:11.449 CEST] [debug] scheduling updates_packagekit_kde tests/update/updates_packagekit_kde.pm [0m[37m[2020-09-02T00:15:11.450 CEST] [debug] scheduling check_system_is_updated tests/update/check_system_is_updated.pm [0m[37m[2020-09-02T00:15:11.451 CEST] [debug] scheduling check_network tests/console/check_network.pm [0m[37m[2020-09-02T00:15:11.452 CEST] [debug] scheduling system_state tests/console/system_state.pm [0m[37m[2020-09-02T00:15:11.454 CEST] [debug] scheduling prepare_test_data tests/console/prepare_test_data.pm [0m[37m[2020-09-02T00:15:11.455 CEST] [debug] scheduling consoletest_setup tests/console/consoletest_setup.pm [0m[37m[2020-09-02T00:15:11.457 CEST] [debug] scheduling keymap_or_locale tests/locale/keymap_or_locale.pm [0m[37m[2020-09-02T00:15:11.459 CEST] [debug] scheduling force_scheduled_tasks tests/console/force_scheduled_tasks.pm [0m[37m[2020-09-02T00:15:11.459 CEST] [debug] scheduling textinfo tests/console/textinfo.pm [0m[37m[2020-09-02T00:15:11.461 CEST] [debug] scheduling hostname tests/console/hostname.pm [0m[37m[2020-09-02T00:15:11.462 CEST] [debug] scheduling x_vt tests/console/x_vt.pm [0m[37m[2020-09-02T00:15:11.463 CEST] [debug] scheduling zypper_lr tests/console/zypper_lr.pm [0m[37m[2020-09-02T00:15:11.464 CEST] [debug] scheduling enable_usb_repo tests/console/enable_usb_repo.pm [0m[37m[2020-09-02T00:15:11.465 CEST] [debug] scheduling ncurses tests/console/ncurses.pm [0m[37m[2020-09-02T00:15:11.470 CEST] [debug] scheduling yast2_lan tests/console/yast2_lan.pm [0m[37m[2020-09-02T00:15:11.471 CEST] [debug] scheduling curl_https tests/console/curl_https.pm [0m[37m[2020-09-02T00:15:11.473 CEST] [debug] scheduling salt tests/console/salt.pm [0m[37m[2020-09-02T00:15:11.474 CEST] [debug] scheduling zypper_in tests/console/zypper_in.pm [0m[37m[2020-09-02T00:15:11.475 CEST] [debug] scheduling zypper_log tests/console/zypper_log.pm [0m[37m[2020-09-02T00:15:11.477 CEST] [debug] scheduling yast2_i tests/console/yast2_i.pm [0m[37m[2020-09-02T00:15:11.479 CEST] [debug] scheduling yast2_bootloader tests/console/yast2_bootloader.pm [0m[37m[2020-09-02T00:15:11.480 CEST] [debug] scheduling vim tests/console/vim.pm [0m[37m[2020-09-02T00:15:11.481 CEST] [debug] scheduling firewall_enabled tests/console/firewall_enabled.pm [0m[37m[2020-09-02T00:15:11.483 CEST] [debug] scheduling sshd tests/console/sshd.pm [0m[37m[2020-09-02T00:15:11.484 CEST] [debug] scheduling ssh_cleanup tests/console/ssh_cleanup.pm [0m[37m[2020-09-02T00:15:11.485 CEST] [debug] scheduling sshfs tests/console/sshfs.pm [0m[37m[2020-09-02T00:15:11.486 CEST] [debug] scheduling mtab tests/console/mtab.pm [0m[37m[2020-09-02T00:15:11.488 CEST] [debug] scheduling orphaned_packages_check tests/console/orphaned_packages_check.pm [0m[37m[2020-09-02T00:15:11.489 CEST] [debug] scheduling consoletest_finish tests/console/consoletest_finish.pm [0m[37m[2020-09-02T00:15:11.490 CEST] [debug] scheduling user_gui_login tests/x11/user_gui_login.pm [0m[37m[2020-09-02T00:15:11.491 CEST] [debug] scheduling desktop_runner tests/x11/desktop_runner.pm [0m[37m[2020-09-02T00:15:11.492 CEST] [debug] scheduling xterm tests/x11/xterm.pm [0m[37m[2020-09-02T00:15:11.493 CEST] [debug] scheduling keymap_or_locale_x11 tests/locale/keymap_or_locale_x11.pm [0m[37m[2020-09-02T00:15:11.495 CEST] [debug] scheduling sshxterm tests/x11/sshxterm.pm [0m[37m[2020-09-02T00:15:11.496 CEST] [debug] scheduling firefox tests/x11/firefox.pm [0m[37m[2020-09-02T00:15:11.497 CEST] [debug] scheduling firefox_audio tests/x11/firefox_audio.pm [0m[37m[2020-09-02T00:15:11.498 CEST] [debug] scheduling chromium tests/x11/chromium.pm [0m[37m[2020-09-02T00:15:11.499 CEST] [debug] scheduling ooffice tests/x11/ooffice.pm [0m[37m[2020-09-02T00:15:11.501 CEST] [debug] scheduling oomath tests/x11/oomath.pm [0m[37m[2020-09-02T00:15:11.502 CEST] [debug] scheduling oocalc tests/x11/oocalc.pm [0m[37m[2020-09-02T00:15:11.503 CEST] [debug] scheduling plasma_browser_integration tests/x11/plasma_browser_integration.pm [0m[37m[2020-09-02T00:15:11.504 CEST] [debug] scheduling khelpcenter tests/x11/khelpcenter.pm [0m[37m[2020-09-02T00:15:11.505 CEST] [debug] scheduling systemsettings5 tests/x11/systemsettings5.pm [0m[37m[2020-09-02T00:15:11.507 CEST] [debug] scheduling dolphin tests/x11/dolphin.pm [0m[37m[2020-09-02T00:15:11.508 CEST] [debug] scheduling glxgears tests/x11/glxgears.pm [0m[37m[2020-09-02T00:15:11.509 CEST] [debug] scheduling desktop_mainmenu tests/x11/desktop_mainmenu.pm [0m[37m[2020-09-02T00:15:11.510 CEST] [debug] scheduling inkscape tests/x11/inkscape.pm [0m[37m[2020-09-02T00:15:11.512 CEST] [debug] scheduling gimp tests/x11/gimp.pm [0m[37m[2020-09-02T00:15:11.513 CEST] [debug] scheduling hexchat tests/x11/hexchat.pm [0m[37m[2020-09-02T00:15:11.515 CEST] [debug] scheduling vlc tests/x11/vlc.pm [0m[37m[2020-09-02T00:15:11.516 CEST] [debug] scheduling kate tests/x11/kate.pm [0m[37m[2020-09-02T00:15:11.517 CEST] [debug] scheduling amarok tests/x11/amarok.pm [0m[37m[2020-09-02T00:15:11.518 CEST] [debug] scheduling kontact tests/x11/kontact.pm [0m[37m[2020-09-02T00:15:11.520 CEST] [debug] scheduling shutdown tests/shutdown/shutdown.pm [0m[2020-09-02T00:15:11.577 CEST] [info] cmdsrv: daemon reachable under http://*:20033/FDK5NTQyiHRYvqGw/ [37m[2020-09-02T00:15:11.579 CEST] [debug] git hash in /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse/products/opensuse/needles: 73ebc3acc3c3cd24f09d9f6c15edc470eba6e5eb [0m[37m[2020-09-02T00:15:11.580 CEST] [debug] init needles from /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse/products/opensuse/needles [0m[2020-09-02T00:15:11.583 CEST] [info] Listening at "http://[::]:20033" Web application available at http://[::]:20033 [37m[2020-09-02T00:15:12.201 CEST] [debug] inst-console-20200224 contains inst-console twice [0m[37m[2020-09-02T00:15:13.370 CEST] [debug] loaded 8184 needles [0m[37m[2020-09-02T00:15:13.634 CEST] [debug] Blocking SIGTERM [0m[37m[2020-09-02T00:15:13.721 CEST] [debug] Unblocking SIGTERM [0m5575: channel_out 15, channel_in 14 [37m[2020-09-02T00:15:13.990 CEST] [debug] Blocking SIGTERM [0m[37m[2020-09-02T00:15:14.122 CEST] [debug] Unblocking SIGTERM [0m5966: cmdpipe 13, rsppipe 16 [37m[2020-09-02T00:15:14.125 CEST] [debug] started mgmt loop with pid 5966 [0mremove_tree qemuscreenshot [37m[2020-09-02T00:15:14.382 CEST] [debug] qemu version detected: 3.1.1.1 [0m[37m[2020-09-02T00:15:14.709 CEST] [debug] running /usr/bin/chattr -f +C /var/lib/openqa/pool/3/raid [0m[37m[2020-09-02T00:15:15.238 CEST] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/3/openSUSE-Jump-15.2-DVD-aarch64-Build72.2-Media.iso [0m[37m[2020-09-02T00:15:15.443 CEST] [debug] Driver backend collected unknown process with pid 6596 and exit status: 0 [0m[37m[2020-09-02T00:15:15.477 CEST] [debug] backend process exited: 0 [0mfailed to start VM at /usr/lib/os-autoinst/backend/driver.pm line 128. [37m[2020-09-02T00:15:15.485 CEST] [debug] stopping command server 5612 because test execution ended through exception [0m[37m[2020-09-02T00:15:16.690 CEST] [debug] done with command server [0m[37m[2020-09-02T00:15:16.690 CEST] [debug] stopping autotest process 5645 [0m[37m[2020-09-02T00:15:17.893 CEST] [debug] done with autotest process [0m5575: EXIT 1 [2020-09-02T00:15:18.0121 CEST] [info] Isotovideo exit status: 1 [2020-09-02T00:15:18.0153 CEST] [info] +++ worker notes +++ [2020-09-02T00:15:18.0154 CEST] [info] End time: 2020-09-01 22:15:18 [2020-09-02T00:15:18.0154 CEST] [info] Result: died [2020-09-02T00:15:18.0238 CEST] [info] Uploading video.ogv [2020-09-02T00:15:18.0319 CEST] [info] Uploading video_time.vtt [2020-09-02T00:15:18.0355 CEST] [info] Uploading vars.json [2020-09-02T00:15:18.0381 CEST] [info] Uploading autoinst-log.txt ``` The message `isotovideo died: failed to start VM at /usr/lib/os-autoinst/backend/driver.pm line 128.` is saved as reason but I'm not sure whether it is really the source of the problem or just a symptom. --- job reference: https://openqa.opensuse.org/tests/1380901 ## Steps to reproduce Find reproducing jobs on production with ``` for i in o3 osd; do ssh $i "sudo -u geekotest psql openqa -c \"select id,t_finished,test,reason from jobs where t_finished >= '2020-09-01' and reason ~ 'isotovideo died: failed to start VM' order by t_finished desc limit 20;\""; done ``` ## Expected result Problem does not happen anymore or if it happens there is more helpful output. ## Suggestions * Check current test code coverage in os-autoinst for the error handling of backend/driver.pm:128 with the line `$self->_send_json({cmd => 'start_vm'}) || die "failed to start VM";` * Ensure the code is properly covered with tests * Try to reproduce the above problem * Improve feedback in these cases