QA » openQA Project » openQA Tests

Observation¶

openQA test in scenario sle-15-Server-DVD-Updates-x86_64-qam_wicked_aggregate_sut@64bit incompletes after t19_teaming_ab_nsna_ping . From autoinst-log.txt:

[2019-11-21T15:25:19.328 CET] [debug] ||| finished t19_teaming_ab_nsna_ping wicked/aggregate/sut at 2019-11-21 14:25:19 (84 s)
[2019-11-21T15:25:19.330 CET] [debug] Loading a VM snapshot lastgood
[2019-11-21T15:25:19.330 CET] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[0]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":600175,"seconds":1574346237}}
[2019-11-21T15:25:19.330 CET] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[1]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":657272,"seconds":1574346237}}
[2019-11-21T15:25:19.331 CET] [debug] Loading snapshot (Current VM state is running).
[2019-11-21T15:25:19.337 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":337351,"seconds":1574346319}}
[2019-11-21T15:25:19.338 CET] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2019-11-21T15:25:21.364 CET] [debug] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 40115 (/usr/bin/isotovideo: backen)
[2019-11-21T15:25:21.368 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/7/raid/hd0-overlay1 /var/lib/openqa/pool/7/raid/hd0-overlay2 32212254720
[2019-11-21T15:25:21.390 CET] [debug] Formatting '/var/lib/openqa/pool/7/raid/hd0-overlay2', fmt=qcow2 size=32212254720 backing_file=/var/lib/openqa/pool/7/raid/hd0-overlay1 cluster_size=65536 lazy_refcounts=off refcount_bits=16
[2019-11-21T15:25:21.391 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/7/raid/cd0-overlay1 /var/lib/openqa/pool/7/raid/cd0-overlay2 665845760
[2019-11-21T15:25:21.410 CET] [debug] Formatting '/var/lib/openqa/pool/7/raid/cd0-overlay2', fmt=qcow2 size=665845760 backing_file=/var/lib/openqa/pool/7/raid/cd0-overlay1 cluster_size=65536 lazy_refcounts=off refcount_bits=16
[2019-11-21T15:25:21.411 CET] [debug] starting: /usr/bin/qemu-system-x86_64 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw hda -global isa-fdc.driveA= -m 1024 -cpu qemu64 -netdev tap,id=qanet0,ifname=tap6,script=no,downscript=no -device virtio-net,netdev=qanet0,mac=52:54:00:12:03:af -netdev tap,id=qanet1,ifname=tap70,script=no,downscript=no -device virtio-net,netdev=qanet1,mac=52:54:00:12:43:af -boot order=c,menu=on,splash-time=5000 -device usb-ehci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :97,share=force-shared -device virtio-serial -chardev socket,path=virtio_console,server,nowait,id=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev socket,path=virtio_console1,server,nowait,id=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay2-file,filename=/var/lib/openqa/pool/7/raid/hd0-overlay2,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay2,file=hd0-overlay2-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0-overlay2,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay2-file,filename=/var/lib/openqa/pool/7/raid/cd0-overlay2,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay2,file=cd0-overlay2-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay2,serial=cd0 -incoming defer
[2019-11-21T15:25:21.417 CET] [debug] Waiting for 0 attempts
[2019-11-21T15:25:22.418 CET] [debug] Waiting for 1 attempts
[2019-11-21T15:25:23.418 CET] [debug] Finished after 2 attempts
[2019-11-21T15:25:23.419 CET] [debug] qmpsocket 14
[2019-11-21T15:25:23.422 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":422209,"seconds":1574346323}}
[2019-11-21T15:25:24.424 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":426431,"seconds":1574346323}}
[2019-11-21T15:25:26.668 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":668448,"seconds":1574346326}}
/usr/lib/os-autoinst/consoles/vnc_base.pm:62:{
  'connect_timeout' => 3,
  'hostname' => 'localhost',
  'port' => 5997
}
[2019-11-21T15:25:26.671 CET] [debug] <<< consoles::virtio_terminal::open_socket(socket_path='/var/lib/openqa/pool/7/virtio_console1')
[2019-11-21T15:25:26.671 CET] [debug] <<< consoles::virtio_terminal::open_socket(socket_path='/var/lib/openqa/pool/7/virtio_console')
[2019-11-21T15:25:26.724 CET] [debug] pointer type 1 0 1024 768 -257
[2019-11-21T15:25:26.724 CET] [debug] led state 0 1 1 -261
[2019-11-21T15:25:26.731 CET] [debug] Restored snapshot
[2019-11-21T15:25:26.731 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50346","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5997","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":669821,"seconds":1574346326}}
[2019-11-21T15:25:26.731 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50346","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5997","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":671201,"seconds":1574346326}}
[2019-11-21T15:25:26.731 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":731641,"seconds":1574346326}}
[2019-11-21T15:25:26.777 CET] [debug] Backend process died, backend errors are reported below in the following lines:
The console 'sut' is not responding (half-open socket?). Make sure the console is reachable or disable stall detection on expected disconnects with '$console->disable_vnc_stalls', for example in case of intended machine shutdown

so the problem seems to be related to forcing a rollback to a previous snapshot.

Reproducible¶

Fails sporadically in about 2/3 cases since multiple weeks at least

Expected result¶

20191120-1 (or more recent)

Further details¶

Always latest result in this scenario: latest