19:28:25 INFO | Avocado-VT 'unknown'
19:28:25 DEBUG| Test parameters:
19:28:25 DEBUG|     _name_map_file = {'machines.cfg': 'arm64-pci', 'subtests.cfg': '(subtest=io-github-autotest-qemu).(subtest=unattended_install).cdrom.extra_cdrom_ks.default_install.aio_threads', 'host-os.cfg': 'Host.RHEL.m8.u1.Host_arch_aarch64', 'guest-os.cfg': 'Guest.Linux.RHEL.7.devel.aarch64', 'guest-hw.cfg': 'bridge.default_bios.no_virtio_rng.(image_backend=filesystem).no_9p_export.smallpages.no_pci_assignable.qcow2.virtio_scsi.smp2.virtio_net', 'tests.cfg': 'qemu_kvm_jeos_quick'}
19:28:25 DEBUG|     _short_name_map_file = {'machines.cfg': 'arm64-pci', 'subtests.cfg': 'io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads', 'host-os.cfg': 'Host.RHEL.m8.u1.Host_arch_aarch64', 'guest-os.cfg': 'Guest.Linux.RHEL.7.devel.aarch64', 'guest-hw.cfg': 'bridge.default_bios.no_virtio_rng.filesystem.no_9p_export.smallpages.no_pci_assignable.qcow2.virtio_scsi.smp2.virtio_net', 'tests.cfg': 'qemu_kvm_jeos_quick'}
19:28:25 DEBUG|     auto_cpu_model = no
19:28:25 DEBUG|     automem = no
19:28:25 DEBUG|     backup_dir = images/
19:28:25 DEBUG|     backup_image = no
19:28:25 DEBUG|     backup_image_after_testing_passed = yes
19:28:25 DEBUG|     backup_image_before_testing = yes
19:28:25 DEBUG|     backup_image_on_check_error = no
19:28:25 DEBUG|     boot_menu = off
19:28:25 DEBUG|     boot_once = d
19:28:25 DEBUG|     boot_order = cdn
19:28:25 DEBUG|     boot_path = images/pxeboot
19:28:25 DEBUG|     catch_monitor = catch_monitor
19:28:25 DEBUG|     cd_format = scsi-cd
19:28:25 DEBUG|     cdrom_cd1 = isos/linux/RHEL-7-devel-aarch64.iso
19:28:25 DEBUG|     cdrom_check_cdrom_pattern = /dev/cdrom-\w+|/dev/cdrom\d*
19:28:25 DEBUG|     cdrom_get_cdrom_cmd = ls /dev/cdrom*
19:28:25 DEBUG|     cdrom_info_cmd = cat /proc/sys/dev/cdrom/info
19:28:25 DEBUG|     cdrom_test_cmd = dd if=%s of=/dev/null bs=1 count=1
19:28:25 DEBUG|     cdrom_unattended = images/rhel7-64/ks.iso
19:28:25 DEBUG|     cdroms = cd1 unattended
19:28:25 DEBUG|     check_image = yes
19:28:25 DEBUG|     cmds_installed_host = 
19:28:25 DEBUG|     connect_uri = default
19:28:25 DEBUG|     convert_ppm_files_to_png = no
19:28:25 DEBUG|     cpu_chk_all_cmd = lscpu | grep "^CPU(s)" | grep -o "[0-9]*"
19:28:25 DEBUG|     cpu_chk_cmd = grep -c "^processor\b" /proc/cpuinfo
19:28:25 DEBUG|     cpu_model = host
19:28:25 DEBUG|     cpu_model_flags = 
19:28:25 DEBUG|     create_vm_libvirt = no
19:28:25 DEBUG|     dep = []
19:28:25 DEBUG|     display = vnc
19:28:25 DEBUG|     download_url_stress = http://people.seas.harvard.edu/~apw/stress/stress-1.0.4.tar.gz
19:28:25 DEBUG|     drive_format = scsi-hd
19:28:25 DEBUG|     drive_index_cd1 = 2
19:28:25 DEBUG|     drive_index_image1 = 0
19:28:25 DEBUG|     drive_index_unattended = 1
19:28:25 DEBUG|     drive_rerror_image1 = 
19:28:25 DEBUG|     drive_werror_image1 = 
19:28:25 DEBUG|     enable_guest_sosreport = no
19:28:25 DEBUG|     enable_host_sosreport = no
19:28:25 DEBUG|     enable_libvirtd_debug_log = yes
19:28:25 DEBUG|     enable_msix_vectors = yes
19:28:25 DEBUG|     enable_remote_host_sosreport = no
19:28:25 DEBUG|     encode_video_files = yes
19:28:25 DEBUG|     env_cleanup = no
19:28:25 DEBUG|     file_transfer_client = scp
19:28:25 DEBUG|     file_transfer_port = 22
19:28:25 DEBUG|     flexible_nic_index = no
19:28:25 DEBUG|     force_create_image = yes
19:28:25 DEBUG|     grub_file = /boot/grub/grub.conf
19:28:25 DEBUG|     guest_dmesg_dump_console = no
19:28:25 DEBUG|     guest_dmesg_ignore = False
19:28:25 DEBUG|     guest_dmesg_level = 3
19:28:25 DEBUG|     guest_port_remote_shell = 22
19:28:25 DEBUG|     guest_port_unattended_install = 12323
19:28:25 DEBUG|     id = io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads
19:28:25 DEBUG|     image_aio = threads
19:28:25 DEBUG|     image_backend = filesystem
19:28:25 DEBUG|     image_chain = 
19:28:25 DEBUG|     image_clone_command = cp --reflink=auto %s %s
19:28:25 DEBUG|     image_copy_on_error = no
19:28:25 DEBUG|     image_format = qcow2
19:28:25 DEBUG|     image_name = images/rhel7devel-aarch64
19:28:25 DEBUG|     image_raw_device = no
19:28:25 DEBUG|     image_remove_command = rm -rf %s
19:28:25 DEBUG|     image_size = 10G
19:28:25 DEBUG|     image_unbootable_pattern = Hard Disk.*not a bootable disk
19:28:25 DEBUG|     image_verify_bootable = no
19:28:25 DEBUG|     images = image1
19:28:25 DEBUG|     inactivity_treshold = 1800
19:28:25 DEBUG|     inactivity_watcher = error
19:28:25 DEBUG|     indirect_image_blacklist = /dev/hda[\d]* /dev/sda[\d]* /dev/sg0 /dev/md0
19:28:25 DEBUG|     initrd = images/rhel7-aarch64/initrd.img
19:28:25 DEBUG|     inputs = 
19:28:25 DEBUG|     install_timeout = 7200
19:28:25 DEBUG|     install_trigger_time = 0
19:28:25 DEBUG|     install_virtio = no
19:28:25 DEBUG|     keep_ppm_files = no
19:28:25 DEBUG|     keep_ppm_files_on_error = no
19:28:25 DEBUG|     keep_screendumps = yes
19:28:25 DEBUG|     keep_screendumps_on_error = yes
19:28:25 DEBUG|     keep_video_files = yes
19:28:25 DEBUG|     keep_video_files_on_error = yes
19:28:25 DEBUG|     kernel = images/rhel7-aarch64/vmlinuz
19:28:25 DEBUG|     kernel_params = ks=cdrom inst.sshd nicdelay=60  earlyprintk=pl011,0x9000000 console=ttyAMA0 debug ignore_loglevel rootwait
19:28:25 DEBUG|     kickstart_reboot_bug = no
19:28:25 DEBUG|     kill_timeout = 60
19:28:25 DEBUG|     kill_unresponsive_vms = yes
19:28:25 DEBUG|     kill_vm = yes
19:28:25 DEBUG|     kill_vm_before_test = no
19:28:25 DEBUG|     kill_vm_gracefully = yes
19:28:25 DEBUG|     kill_vm_libvirt = no
19:28:25 DEBUG|     kill_vm_on_error = yes
19:28:25 DEBUG|     libvirt_controller = virtio-scsi
19:28:25 DEBUG|     libvirtd_debug_file = 
19:28:25 DEBUG|     libvirtd_debug_level = 2
19:28:25 DEBUG|     libvirtd_log_cleanup = yes
19:28:25 DEBUG|     local_ip = ENTER.YOUR.LOCAL.EXAMPLE.COM
19:28:25 DEBUG|     local_pwd = 
19:28:25 DEBUG|     login_timeout = 360
19:28:25 DEBUG|     lowest_mem = 512
19:28:25 DEBUG|     machine_type = arm64-pci:virt
19:28:25 DEBUG|     machine_type_extra_params = gic-version=host
19:28:25 DEBUG|     main_vm = avocado-vt-vm1
19:28:25 DEBUG|     malloc_perturb = yes
19:28:25 DEBUG|     medium = cdrom
19:28:25 DEBUG|     mem = 4096
19:28:25 DEBUG|     mem_chk_cmd = dmidecode -t 17 | awk -F: '/Size/ {print $2}'
19:28:25 DEBUG|     mem_chk_cur_cmd = grep MemTotal /proc/meminfo
19:28:25 DEBUG|     mem_chk_re_str = [^\$]([0-9]+)
19:28:25 DEBUG|     memballoon_model = virtio
19:28:25 DEBUG|     migrate_dest_host = ENTER.YOUR.DEST.EXAMPLE.COM
19:28:25 DEBUG|     migrate_dest_pwd = PASSWORD.DEST.EXAMPLE
19:28:25 DEBUG|     migrate_load_vms = 
19:28:25 DEBUG|     migrate_main_vm = avocado-vt-vm1
19:28:25 DEBUG|     migrate_port = 49152
19:28:25 DEBUG|     migrate_proto = tcp
19:28:25 DEBUG|     migrate_shared_storage = SHARED_IMAGE.EXAMPLE
19:28:25 DEBUG|     migrate_source_host = ENTER.YOUR.SOURCE.EXAMPLE.COM
19:28:25 DEBUG|     migrate_source_pwd = PASSWORD.SOURCE.EXAMPLE
19:28:25 DEBUG|     migrate_vms = 
19:28:25 DEBUG|     migration_setup = no
19:28:25 DEBUG|     monitor_type = human
19:28:25 DEBUG|     monitors = qmpmonitor1
19:28:25 DEBUG|     name = qemu_kvm_jeos_quick.bridge.default_bios.no_virtio_rng.(image_backend=filesystem).no_9p_export.smallpages.no_pci_assignable.qcow2.virtio_scsi.smp2.virtio_net.Guest.Linux.RHEL.7.devel.aarch64.Host.RHEL.m8.u1.Host_arch_aarch64.(subtest=io-github-autotest-qemu).(subtest=unattended_install).cdrom.extra_cdrom_ks.default_install.aio_threads.arm64-pci
19:28:25 DEBUG|     netdev_peer_re = \s{2,}(.*?): .*?\\\s(.*?):
19:28:25 DEBUG|     netdst = virbr0
19:28:25 DEBUG|     nettype = bridge
19:28:25 DEBUG|     nic_model = virtio
19:28:25 DEBUG|     nics = nic1
19:28:25 DEBUG|     os_type = linux
19:28:25 DEBUG|     os_variant = rhel7
19:28:25 DEBUG|     other_tests_dirs = 
19:28:25 DEBUG|     password = 123456
19:28:25 DEBUG|     paused_after_start_vm = no
19:28:25 DEBUG|     pci_assignable = no
19:28:25 DEBUG|     pcie_extra_root_port = 2
19:28:25 DEBUG|     ping_pong = 5
19:28:25 DEBUG|     profilers = kvm_stat
19:28:25 DEBUG|     provider = io-github-autotest-qemu
19:28:25 DEBUG|     qemu_binary = /home/jenkins/aarch64/qemu-master-build/bin/qemu-system-aarch64
19:28:25 DEBUG|     qemu_dst_binary = /home/jenkins/aarch64/qemu-master-build/bin/qemu-system-aarch64
19:28:25 DEBUG|     qemu_img_binary = /home/jenkins/aarch64/qemu-master-build/bin/qemu-img
19:28:25 DEBUG|     qemu_io_binary = /home/jenkins/aarch64/qemu-master-build/bin/qemu-io
19:28:25 DEBUG|     qemu_sandbox = 
19:28:25 DEBUG|     qemu_stop = on
19:28:25 DEBUG|     random_trigger = no
19:28:25 DEBUG|     reboot_command = shutdown -r now
19:28:25 DEBUG|     redirs = remote_shell unattended_install
19:28:25 DEBUG|     remote_ip = ENTER.YOUR.REMOTE.EXAMPLE.COM
19:28:25 DEBUG|     remote_pwd = 
19:28:25 DEBUG|     remote_user = root
19:28:25 DEBUG|     remove_image_image1 = no
19:28:25 DEBUG|     restore_image = no
19:28:25 DEBUG|     restore_image_after_testing = yes
19:28:25 DEBUG|     restore_image_on_check_error = no
19:28:25 DEBUG|     rpmbuild_path = /root/rpmbuild/
19:28:25 DEBUG|     run_tcpdump = yes
19:28:25 DEBUG|     screendump_delay = 5
19:28:25 DEBUG|     screendump_quality = 30
19:28:25 DEBUG|     screendump_temp_dir = /dev/shm
19:28:25 DEBUG|     screendump_verbose = no
19:28:25 DEBUG|     scsi_hba = virtio-scsi-pci
19:28:25 DEBUG|     serial_type = isa-serial
19:28:25 DEBUG|     serials = serial0
19:28:25 DEBUG|     shell_client = ssh
19:28:25 DEBUG|     shell_linesep = \n
19:28:25 DEBUG|     shell_port = 22
19:28:25 DEBUG|     shell_prompt = ^\[.*\][\#\$]\s*$
19:28:25 DEBUG|     shortname = qcow2.virtio_scsi.smp2.virtio_net.Guest.RHEL.7.devel.aarch64.io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads.arm64-pci
19:28:25 DEBUG|     shutdown_cleanly = yes
19:28:25 DEBUG|     shutdown_cleanly_timeout = 120
19:28:25 DEBUG|     shutdown_command = shutdown -h now
19:28:25 DEBUG|     skip_cluster_leak_warn = no
19:28:25 DEBUG|     skip_image_check_during_running = no
19:28:25 DEBUG|     skip_image_processing = no
19:28:25 DEBUG|     smp = 2
19:28:25 DEBUG|     start_vm = no
19:28:25 DEBUG|     status_test_command = echo $?
19:28:25 DEBUG|     store_vm_register = no
19:28:25 DEBUG|     stress_args = --cpu 4 --io 4 --vm 2 --vm-bytes 256M
19:28:25 DEBUG|     stress_install_from_repo = no
19:28:25 DEBUG|     strict_mode = no
19:28:25 DEBUG|     subtest = io-github-autotest-qemu.unattended_install
19:28:25 DEBUG|     syslog_server_enabled = no
19:28:25 DEBUG|     syslog_server_proto = udp
19:28:25 DEBUG|     sysprep_options = --operations machine-id
19:28:25 DEBUG|     sysprep_required = no
19:28:25 DEBUG|     take_regular_screendumps = no
19:28:25 DEBUG|     test_timeout = 14400
19:28:25 DEBUG|     type = unattended_install
19:28:25 DEBUG|     unattended_delivery_method = cdrom
19:28:25 DEBUG|     unattended_file = unattended/RHEL-7-devel.ks
19:28:25 DEBUG|     unattended_file_kernel_param_name = ks
19:28:25 DEBUG|     url = http://download.devel.redhat.com/composes/finished/latest-RHEL-8/compose/BaseOS/aarch64/os/
19:28:25 DEBUG|     url_auto_ip = 
19:28:25 DEBUG|     usb_bus = usb1.0
19:28:25 DEBUG|     usb_controller = xhci
19:28:25 DEBUG|     usb_devices = tablet1
19:28:25 DEBUG|     usb_max_port = 6
19:28:25 DEBUG|     usb_type = qemu-xhci
19:28:25 DEBUG|     usb_type_tablet1 = usb-tablet
19:28:25 DEBUG|     usb_type_usb1 = qemu-xhci
19:28:25 DEBUG|     usbs = usb1
19:28:25 DEBUG|     use_autostart = no
19:28:25 DEBUG|     use_check_cpu = yes
19:28:25 DEBUG|     use_debug = yes
19:28:25 DEBUG|     use_no_reboot = no
19:28:25 DEBUG|     use_os_type = yes
19:28:25 DEBUG|     use_os_variant = no
19:28:25 DEBUG|     use_virt_install_wait = no
19:28:25 DEBUG|     used_cpus = 2
19:28:25 DEBUG|     used_mem = 512
19:28:25 DEBUG|     username = root
19:28:25 DEBUG|     verify_guest_dmesg = yes
19:28:25 DEBUG|     verify_host_dmesg = yes
19:28:25 DEBUG|     vfd_size = 1440k
19:28:25 DEBUG|     vga = virtio
19:28:25 DEBUG|     vga_use_legacy_expression = no
19:28:25 DEBUG|     vir_domain_undefine_nvram = yes
19:28:25 DEBUG|     virt_install_wait_time = 300
19:28:25 DEBUG|     virt_test_type = qemu libvirt
19:28:25 DEBUG|     virtinstall_extra_args = 
19:28:25 DEBUG|     vm_arch_name = aarch64
19:28:25 DEBUG|     vm_mem_minimum = 2G
19:28:25 DEBUG|     vm_monitor_exit_status = no
19:28:25 DEBUG|     vm_register_delay = 5
19:28:25 DEBUG|     vm_type = qemu
19:28:25 DEBUG|     vms = avocado-vt-vm1
19:28:25 DEBUG|     vnc_autoport = yes
19:28:25 DEBUG| Searching for test modules that match 'type = unattended_install' and 'provider = io-github-autotest-qemu' on this cartesian dict
19:28:25 DEBUG| Found subtest module /var/lib/libvirt/images/avocado/avocado-vt/test-providers.d/downloads/io-github-autotest-qemu/generic/tests/unattended_install.py
19:28:27 DEBUG| KVM version: 4.18.0-134.el8.aarch64
19:28:29 DEBUG| KVM userspace version(qemu): 4.1.50 (v4.1.0-132-gafd7605393-dirty)
19:28:29 INFO | Running 'true'
19:28:29 INFO | Command 'true' finished with 0 after 0.0015230178833007812s
19:28:29 INFO | Running 'ps -o comm 1'
19:28:29 DEBUG| [stdout] COMMAND
19:28:29 INFO | Command 'ps -o comm 1' finished with 0 after 0.05569195747375488s
19:28:29 DEBUG| [stdout] systemd
19:28:29 INFO | Checking disk size on /var/lib/libvirt/images/avocado/avocado-vt/images.
19:28:29 DEBUG| Image backup /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2.backup already exists, skipping...
19:28:29 INFO | Create image on local fs.
19:28:29 INFO | Context: preprocessing --> Create image by command: /home/jenkins/aarch64/qemu-master-build/bin/qemu-img create -f qcow2 /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2 10G
19:28:30 INFO | Starting unattended install setup
19:28:30 DEBUG| Automatically chosen class for iso9660: isoinfo
19:28:30 INFO | Running 'isoinfo -i /var/lib/libvirt/images/avocado/avocado-vt/isos/linux/RHEL-7-devel-aarch64.iso -d'
19:28:30 DEBUG| [stdout] CD-ROM is in ISO 9660 format
19:28:30 INFO | Command 'isoinfo -i /var/lib/libvirt/images/avocado/avocado-vt/isos/linux/RHEL-7-devel-aarch64.iso -d' finished with 0 after 0.0023012161254882812s
19:28:30 DEBUG| [stdout] System id: LINUX
19:28:30 DEBUG| [stdout] Volume id: RHEL-8-0-0-BaseOS-aarch64
19:28:30 DEBUG| [stdout] Volume set id: 
19:28:30 DEBUG| [stdout] Publisher id: 
19:28:30 DEBUG| [stdout] Data preparer id: 
19:28:30 DEBUG| [stdout] Application id: GENISOIMAGE ISO 9660/HFS FILESYSTEM CREATOR (C) 1993 E.YOUNGDALE (C) 1997-2006 J.PEARSON/J.SCHILLING (C) 2006-2007 CDRKIT TEAM
19:28:30 DEBUG| [stdout] Copyright File id: 
19:28:30 DEBUG| [stdout] Abstract File id: 
19:28:30 DEBUG| [stdout] Bibliographic File id: 
19:28:30 DEBUG| [stdout] Volume set size is: 1
19:28:30 DEBUG| [stdout] Volume set sequence number is: 1
19:28:30 DEBUG| [stdout] Logical block size is: 2048
19:28:30 DEBUG| [stdout] Volume size is: 2511949
19:28:30 DEBUG| [stdout] El Torito VD version 1 found, boot catalog is in sector 795
19:28:30 DEBUG| [stdout] Joliet with UCS level 3 found
19:28:30 DEBUG| [stdout] Rock Ridge signatures version 1 found
19:28:30 DEBUG| [stdout] Eltorito validation header:
19:28:30 DEBUG| [stdout]     Hid 1
19:28:30 DEBUG| [stdout]     Arch 239 (Unknown Arch)
19:28:30 DEBUG| [stdout]     ID ''
19:28:30 DEBUG| [stdout]     Key 55 AA
19:28:30 DEBUG| [stdout]     Eltorito defaultboot header:
19:28:30 DEBUG| [stdout]         Bootid 88 (bootable)
19:28:30 DEBUG| [stdout]         Boot media 0 (No Emulation Boot)
19:28:30 DEBUG| [stdout]         Load segment 0
19:28:30 DEBUG| [stdout]         Sys type 0
19:28:30 DEBUG| [stdout]         Nsect 32CC
19:28:30 DEBUG| [stdout]         Bootoff EE7 3815
19:28:32 INFO | Running 'cat /proc/mounts'
19:28:32 DEBUG| [stdout] sysfs /sys sysfs rw,seclabel,nosuid,nodev,noexec,relatime 0 0
19:28:32 INFO | Command 'cat /proc/mounts' finished with 0 after 0.005123138427734375s
19:28:32 DEBUG| [stdout] proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] devtmpfs /dev devtmpfs rw,seclabel,nosuid,size=33202560k,nr_inodes=518790,mode=755 0 0
19:28:32 DEBUG| [stdout] securityfs /sys/kernel/security securityfs rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] tmpfs /dev/shm tmpfs rw,seclabel,nosuid,nodev 0 0
19:28:32 DEBUG| [stdout] devpts /dev/pts devpts rw,seclabel,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
19:28:32 DEBUG| [stdout] tmpfs /run tmpfs rw,seclabel,nosuid,nodev,mode=755 0 0
19:28:32 DEBUG| [stdout] tmpfs /sys/fs/cgroup tmpfs ro,seclabel,nosuid,nodev,noexec,mode=755 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/systemd cgroup rw,seclabel,nosuid,nodev,noexec,relatime,xattr,release_agent=/usr/lib/systemd/systemd-cgroups-agent,name=systemd 0 0
19:28:32 DEBUG| [stdout] pstore /sys/fs/pstore pstore rw,seclabel,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] efivarfs /sys/firmware/efi/efivars efivarfs rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] bpf /sys/fs/bpf bpf rw,nosuid,nodev,noexec,relatime,mode=700 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/net_cls,net_prio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,net_cls,net_prio 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/memory cgroup rw,seclabel,nosuid,nodev,noexec,relatime,memory 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/devices cgroup rw,seclabel,nosuid,nodev,noexec,relatime,devices 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/cpu,cpuacct cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpu,cpuacct 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/freezer cgroup rw,seclabel,nosuid,nodev,noexec,relatime,freezer 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/perf_event cgroup rw,seclabel,nosuid,nodev,noexec,relatime,perf_event 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/blkio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,blkio 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/cpuset cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpuset 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/rdma cgroup rw,seclabel,nosuid,nodev,noexec,relatime,rdma 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/pids cgroup rw,seclabel,nosuid,nodev,noexec,relatime,pids 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/hugetlb cgroup rw,seclabel,nosuid,nodev,noexec,relatime,hugetlb 0 0
19:28:32 DEBUG| [stdout] configfs /sys/kernel/config configfs rw,relatime 0 0
19:28:32 DEBUG| [stdout] /dev/mapper/rhel_gigabyte--r120--15-root / xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] selinuxfs /sys/fs/selinux selinuxfs rw,relatime 0 0
19:28:32 DEBUG| [stdout] systemd-1 /proc/sys/fs/binfmt_misc autofs rw,relatime,fd=46,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=1225 0 0
19:28:32 DEBUG| [stdout] debugfs /sys/kernel/debug debugfs rw,seclabel,relatime 0 0
19:28:32 DEBUG| [stdout] mqueue /dev/mqueue mqueue rw,seclabel,relatime 0 0
19:28:32 DEBUG| [stdout] hugetlbfs /dev/hugepages hugetlbfs rw,seclabel,relatime,pagesize=512M 0 0
19:28:32 DEBUG| [stdout] /dev/sda2 /boot xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] /dev/sda1 /boot/efi vfat rw,relatime,fmask=0077,dmask=0077,codepage=437,iocharset=ascii,shortname=winnt,errors=remount-ro 0 0
19:28:32 DEBUG| [stdout] /dev/mapper/rhel_gigabyte--r120--15-home /home xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] sunrpc /var/lib/nfs/rpc_pipefs rpc_pipefs rw,relatime 0 0
19:28:32 DEBUG| [stdout] tmpfs /run/user/0 tmpfs rw,seclabel,nosuid,nodev,relatime,size=6643392k,mode=700 0 0
19:28:32 DEBUG| [stdout] binfmt_misc /proc/sys/fs/binfmt_misc binfmt_misc rw,relatime 0 0
19:28:32 DEBUG| Unattended install contents:
19:28:32 DEBUG| install
19:28:32 DEBUG| cdrom
19:28:32 DEBUG| text
19:28:32 DEBUG| poweroff
19:28:32 DEBUG| lang en_US.UTF-8
19:28:32 DEBUG| keyboard us
19:28:32 DEBUG| network --onboot yes --device eth0 --bootproto dhcp
19:28:32 DEBUG| rootpw --plaintext 123456
19:28:32 DEBUG| firstboot --disable
19:28:32 DEBUG| user --name=test --password=123456
19:28:32 DEBUG| firewall --enabled --ssh
19:28:32 DEBUG| selinux --enforcing
19:28:32 DEBUG| timezone --utc America/New_York
19:28:32 DEBUG| bootloader --location=mbr --append="console=tty0 console=ttyS0,115200"
19:28:32 DEBUG| zerombr
19:28:32 DEBUG| 
19:28:32 DEBUG| clearpart --all --initlabel
19:28:32 DEBUG| autopart
19:28:32 DEBUG| xconfig --startxonboot
19:28:32 DEBUG| 
19:28:32 DEBUG| %packages --ignoremissing
19:28:32 DEBUG| @base
19:28:32 DEBUG| @core
19:28:32 DEBUG| @development
19:28:32 DEBUG| @additional-devel
19:28:32 DEBUG| @debugging
19:28:32 DEBUG| @network-tools
19:28:32 DEBUG| @x11
19:28:32 DEBUG| @gnome-desktop
19:28:32 DEBUG| @fonts
19:28:32 DEBUG| @smart-card
19:28:32 DEBUG| gnome-utils
19:28:32 DEBUG| python-imaging
19:28:32 DEBUG| python-six
19:28:32 DEBUG| pyparsing
19:28:32 DEBUG| net-tools
19:28:32 DEBUG| NetworkManager
19:28:32 DEBUG| ntpdate
19:28:32 DEBUG| dconf
19:28:32 DEBUG| watchdog
19:28:32 DEBUG| coreutils
19:28:32 DEBUG| usbutils
19:28:32 DEBUG| spice-xpi
19:28:32 DEBUG| spice-gtk3
19:28:32 DEBUG| docbook-utils
19:28:32 DEBUG| sgml-common
19:28:32 DEBUG| openjade
19:28:32 DEBUG| virt-viewer
19:28:32 DEBUG| pulseaudio-libs-devel
19:28:32 DEBUG| mesa-libGL-devel
19:28:32 DEBUG| pygtk2-devel
19:28:32 DEBUG| libjpeg-turbo-devel
19:28:32 DEBUG| spice-vdagent
19:28:32 DEBUG| usbredir
19:28:32 DEBUG| SDL
19:28:32 DEBUG| totem
19:28:32 DEBUG| dmidecode
19:28:32 DEBUG| alsa-utils
19:28:32 DEBUG| sg3_utils
19:28:32 DEBUG| -gnome-initial-setup
19:28:32 DEBUG| %end
19:28:32 DEBUG| 
19:28:32 DEBUG| %post
19:28:32 DEBUG| # Output to all consoles defined in /proc/consoles, use "major:minor" as
19:28:32 DEBUG| # device names are unreliable on some platforms
19:28:32 DEBUG| # https://bugzilla.redhat.com/show_bug.cgi?id=1351968
19:28:32 DEBUG| function ECHO { for TTY in `cat /proc/consoles | awk '{print $NF}'`; do source "/sys/dev/char/$TTY/uevent" && echo "$*" > /dev/$DEVNAME; done }
19:28:32 DEBUG| ECHO "OS install is completed"
19:28:32 DEBUG| ECHO "remove rhgb quiet by grubby"
19:28:32 DEBUG| grubby --remove-args="rhgb quiet" --update-kernel=$(grubby --default-kernel)
19:28:32 DEBUG| ECHO "dhclient"
19:28:32 DEBUG| dhclient
19:28:32 DEBUG| ECHO "chkconfig sshd on"
19:28:32 DEBUG| chkconfig sshd on
19:28:32 DEBUG| ECHO "iptables -F"
19:28:32 DEBUG| iptables -F
19:28:32 DEBUG| ECHO "echo 0 > selinux/enforce"
19:28:32 DEBUG| echo 0 > /selinux/enforce
19:28:32 DEBUG| ECHO "chkconfig NetworkManager on"
19:28:32 DEBUG| chkconfig NetworkManager on
19:28:32 DEBUG| ECHO "update ifcfg-eth0"
19:28:32 DEBUG| sed -i "/^HWADDR/d" /etc/sysconfig/network-scripts/ifcfg-eth0
19:28:32 DEBUG| ECHO "Disable lock cdrom udev rules"
19:28:32 DEBUG| sed -i "/--lock-media/s/^/#/" /usr/lib/udev/rules.d/60-cdrom_id.rules 2>/dev/null>&1
19:28:32 DEBUG| #Workaround for graphical boot as anaconda seems to always instert skipx
19:28:32 DEBUG| systemctl set-default graphical.target
19:28:32 DEBUG| sed -i "/^HWADDR/d" /etc/sysconfig/network-scripts/ifcfg-*
19:28:32 DEBUG| sed -i "s/ONBOOT=no/ONBOOT=yes/" /etc/sysconfig/network-scripts/ifcfg-*
19:28:32 DEBUG| cat > '/etc/gdm/custom.conf' << EOF
19:28:32 DEBUG| [daemon]
19:28:32 DEBUG| AutomaticLogin=test
19:28:32 DEBUG| AutomaticLoginEnable=True
19:28:32 DEBUG| EOF
19:28:32 DEBUG| cat >> '/etc/sudoers' << EOF
19:28:32 DEBUG| test ALL = NOPASSWD: /sbin/shutdown -r now,/sbin/shutdown -h now
19:28:32 DEBUG| EOF
19:28:32 DEBUG| cat >> '/home/test/.bashrc' << EOF
19:28:32 DEBUG| alias shutdown='sudo shutdown'
19:28:32 DEBUG| EOF
19:28:32 DEBUG| ECHO 'Post set up finished'
19:28:32 DEBUG| %end
19:28:32 INFO | Running 'cat /proc/mounts'
19:28:32 DEBUG| [stdout] sysfs /sys sysfs rw,seclabel,nosuid,nodev,noexec,relatime 0 0
19:28:32 INFO | Command 'cat /proc/mounts' finished with 0 after 0.004851341247558594s
19:28:32 DEBUG| [stdout] proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] devtmpfs /dev devtmpfs rw,seclabel,nosuid,size=33202560k,nr_inodes=518790,mode=755 0 0
19:28:32 DEBUG| [stdout] securityfs /sys/kernel/security securityfs rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] tmpfs /dev/shm tmpfs rw,seclabel,nosuid,nodev 0 0
19:28:32 DEBUG| [stdout] devpts /dev/pts devpts rw,seclabel,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
19:28:32 DEBUG| [stdout] tmpfs /run tmpfs rw,seclabel,nosuid,nodev,mode=755 0 0
19:28:32 DEBUG| [stdout] tmpfs /sys/fs/cgroup tmpfs ro,seclabel,nosuid,nodev,noexec,mode=755 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/systemd cgroup rw,seclabel,nosuid,nodev,noexec,relatime,xattr,release_agent=/usr/lib/systemd/systemd-cgroups-agent,name=systemd 0 0
19:28:32 DEBUG| [stdout] pstore /sys/fs/pstore pstore rw,seclabel,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] efivarfs /sys/firmware/efi/efivars efivarfs rw,nosuid,nodev,noexec,relatime 0 0
19:28:32 DEBUG| [stdout] bpf /sys/fs/bpf bpf rw,nosuid,nodev,noexec,relatime,mode=700 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/net_cls,net_prio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,net_cls,net_prio 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/memory cgroup rw,seclabel,nosuid,nodev,noexec,relatime,memory 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/devices cgroup rw,seclabel,nosuid,nodev,noexec,relatime,devices 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/cpu,cpuacct cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpu,cpuacct 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/freezer cgroup rw,seclabel,nosuid,nodev,noexec,relatime,freezer 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/perf_event cgroup rw,seclabel,nosuid,nodev,noexec,relatime,perf_event 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/blkio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,blkio 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/cpuset cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpuset 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/rdma cgroup rw,seclabel,nosuid,nodev,noexec,relatime,rdma 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/pids cgroup rw,seclabel,nosuid,nodev,noexec,relatime,pids 0 0
19:28:32 DEBUG| [stdout] cgroup /sys/fs/cgroup/hugetlb cgroup rw,seclabel,nosuid,nodev,noexec,relatime,hugetlb 0 0
19:28:32 DEBUG| [stdout] configfs /sys/kernel/config configfs rw,relatime 0 0
19:28:32 DEBUG| [stdout] /dev/mapper/rhel_gigabyte--r120--15-root / xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] selinuxfs /sys/fs/selinux selinuxfs rw,relatime 0 0
19:28:32 DEBUG| [stdout] systemd-1 /proc/sys/fs/binfmt_misc autofs rw,relatime,fd=46,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=1225 0 0
19:28:32 DEBUG| [stdout] debugfs /sys/kernel/debug debugfs rw,seclabel,relatime 0 0
19:28:32 DEBUG| [stdout] mqueue /dev/mqueue mqueue rw,seclabel,relatime 0 0
19:28:32 DEBUG| [stdout] hugetlbfs /dev/hugepages hugetlbfs rw,seclabel,relatime,pagesize=512M 0 0
19:28:32 DEBUG| [stdout] /dev/sda2 /boot xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] /dev/sda1 /boot/efi vfat rw,relatime,fmask=0077,dmask=0077,codepage=437,iocharset=ascii,shortname=winnt,errors=remount-ro 0 0
19:28:32 DEBUG| [stdout] /dev/mapper/rhel_gigabyte--r120--15-home /home xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
19:28:32 DEBUG| [stdout] sunrpc /var/lib/nfs/rpc_pipefs rpc_pipefs rw,relatime 0 0
19:28:32 DEBUG| [stdout] tmpfs /run/user/0 tmpfs rw,seclabel,nosuid,nodev,relatime,size=6643392k,mode=700 0 0
19:28:32 DEBUG| [stdout] binfmt_misc /proc/sys/fs/binfmt_misc binfmt_misc rw,relatime 0 0
19:28:32 DEBUG| unattended install CD image /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7-64/ks.iso successfully created
19:28:32 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/usr/share/Modules/bin', '/bin', '/usr/bin', '/usr/libexec', '/sbin', '/usr/local/bin', '/usr/local/sbin', '/usr/sbin']
19:28:33 INFO | Running '/home/jenkins/aarch64/qemu-master-build/bin/qemu-system-aarch64 -version'
19:28:33 DEBUG| [stdout] QEMU emulator version 4.1.50 (v4.1.0-132-gafd7605393-dirty)
19:28:33 DEBUG| [stdout] Copyright (c) 2003-2019 Fabrice Bellard and the QEMU Project developers
19:28:33 INFO | Command '/home/jenkins/aarch64/qemu-master-build/bin/qemu-system-aarch64 -version' finished with 0 after 0.6501872539520264s
19:28:33 DEBUG| Generating random mac address for nic
19:28:34 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/usr/share/Modules/bin', '/bin', '/usr/bin', '/usr/libexec', '/sbin', '/usr/local/bin', '/usr/local/sbin', '/usr/sbin']
19:28:34 DEBUG| Adding VM avocado-vt-vm1 NIC ifname t0-1UZNrU to bridge virbr0
19:28:34 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/usr/share/Modules/bin', '/bin', '/usr/bin', '/usr/libexec', '/sbin', '/usr/local/bin', '/usr/local/sbin', '/usr/sbin']
19:28:39 WARNI| Support for aarch64 is highly experimental!
19:28:42 DEBUG| Detected CPU vendor as 'unknown'
19:28:42 ERROR| Non existing CPU model host will be passed to qemu (wrong config or negative test)
19:28:43 WARNI| -boot on arm64-pci:virt is usually not supported, use bootindex instead.
19:28:43 DEBUG| qemu will run in KVM mode
19:28:43 DEBUG| Devices of avocado-vt-vm1: [t'PREFIX',t'qemu',t'-S',t'vmname',t'AAVMF_CODE',t'AAVMF_VARS',t'machine',t'gpex-root',t'nodefaults',a'virtio-gpu-pci',t'HMP-qmpmonitor1',t'HMP-catch_monitor',t'SER-serial0',t'isa-log',pcie.0-root-port-2,usb1,pcie.0-root-port-3,virtio_scsi_pci0,file_image1,drive_image1,image1,pcie.0-root-port-4,idooTV42,t'NET-bridge',t'mem',t'smp',t'cpu',file_cd1,drive_cd1,cd1,file_unattended,drive_unattended,unattended,usb-tablet1,t'kernel',t'kernel-params',t'initrd',t'tcp-redir',t'tcp-redir',t'display',t'rtc',t'bootmenu',t'kvm',pcie_extra_root_port_0,pcie_extra_root_port_1]
19:28:43 DEBUG| Buses of avocado-vt-vm1
  pcie_extra_root_port_1(PCIE): {}
  pcie_extra_root_port_0(PCIE): {}
  drive_unattended(QDrive): {drive:unattended}
  drive_cd1(QDrive): {drive:cd1}
  pcie.0-root-port-4(PCIE): {0x0-0x0:idooTV42}
  drive_image1(QDrive): {drive:image1}
  virtio_scsi_pci0.0(virtio-scsi-pci): {0-0:image1,1-0:cd1,2-0:unattended}
  pcie.0-root-port-3(PCIE): {0x0-0x0:virtio_scsi_pci0}
  usb1.0(xhci): {1:usb-tablet1}
  pcie.0-root-port-2(PCIE): {0x0-0x0:usb1}
  _PCI_CHASSIS_NR(None): {}
  _PCI_CHASSIS(None): {}
  pcie.0(PCIE): {0x0-0x0:t'gpex-root',0x1-0x0:a'virtio-gpu-pci',0x2-0x0:pcie.0-root-port-2,0x3-0x0:pcie.0-root-port-3,0x4-0x0:pcie.0-root-port-4,0x5-0x0:pcie_extra_root_port_0,0x6-0x0:pcie_extra_root_port_1}
19:28:43 INFO | Running qemu command (reformatted):
MALLOC_PERTURB_=1  /home/jenkins/aarch64/qemu-master-build/bin/qemu-system-aarch64 \
    -S  \
    -name 'avocado-vt-vm1' \
    -drive file=/usr/share/AAVMF/AAVMF_CODE.fd,if=pflash,format=raw,unit=0,readonly=on \
    -drive file=/var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64_AAVMF_VARS.fd,if=pflash,format=raw,unit=1 \
    -machine virt,gic-version=host  \
    -nodefaults \
    -device virtio-gpu-pci,bus=pcie.0,addr=0x1  \
    -chardev socket,id=hmp_id_qmpmonitor1,path=/var/tmp/avocado_tvjh5pxy/monitor-qmpmonitor1-20190818-192502-6nUqJjFV,server,nowait \
    -mon chardev=hmp_id_qmpmonitor1,mode=readline  \
    -chardev socket,id=hmp_id_catch_monitor,path=/var/tmp/avocado_tvjh5pxy/monitor-catch_monitor-20190818-192502-6nUqJjFV,server,nowait \
    -mon chardev=hmp_id_catch_monitor,mode=readline  \
    -serial unix:'/var/tmp/avocado_tvjh5pxy/serial-serial0-20190818-192502-6nUqJjFV',server,nowait \
    -device pcie-root-port,id=pcie.0-root-port-2,slot=2,chassis=2,addr=0x2,bus=pcie.0 \
    -device qemu-xhci,id=usb1,bus=pcie.0-root-port-2,addr=0x0 \
    -device pcie-root-port,id=pcie.0-root-port-3,slot=3,chassis=3,addr=0x3,bus=pcie.0 \
    -device virtio-scsi-pci,id=virtio_scsi_pci0,bus=pcie.0-root-port-3,addr=0x0 \
    -blockdev node-name=file_image1,driver=file,filename=/var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2 \
    -blockdev node-name=drive_image1,driver=qcow2,file=file_image1 \
    -device scsi-hd,id=image1,drive=drive_image1 \
    -device pcie-root-port,id=pcie.0-root-port-4,slot=4,chassis=4,addr=0x4,bus=pcie.0 \
    -device virtio-net-pci,mac=9a:30:63:fc:96:fc,rombar=0,id=idooTV42,netdev=idAVN8sc,bus=pcie.0-root-port-4,addr=0x0  \
    -netdev tap,id=idAVN8sc,fd=19 \
    -m 4096  \
    -smp 2,maxcpus=2,cores=1,threads=1,sockets=2  \
    -cpu 'host' \
    -blockdev node-name=file_cd1,driver=file,read-only=on,filename=/home/isos/RHEL-8.0.0-20190404.2-aarch64-dvd1.iso \
    -blockdev node-name=drive_cd1,driver=raw,read-only=on,file=file_cd1 \
    -device scsi-cd,id=cd1,drive=drive_cd1 \
    -blockdev node-name=file_unattended,driver=file,read-only=on,filename=/var/lib/libvirt/images/avocado/avocado-vt/images/rhel7-64/ks.iso \
    -blockdev node-name=drive_unattended,driver=raw,read-only=on,file=file_unattended \
    -device scsi-cd,id=unattended,drive=drive_unattended \
    -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1  \
    -kernel '/var/lib/libvirt/images/avocado/avocado-vt/images/rhel7-aarch64/vmlinuz'  \
    -append 'ks=cdrom inst.sshd nicdelay=60  earlyprintk=pl011,0x9000000 console=ttyAMA0 debug ignore_loglevel rootwait'  \
    -initrd '/var/lib/libvirt/images/avocado/avocado-vt/images/rhel7-aarch64/initrd.img'  \
    -vnc :0  \
    -rtc base=utc,clock=host \
    -enable-kvm \
    -device pcie-root-port,id=pcie_extra_root_port_0,slot=5,chassis=5,addr=0x5,bus=pcie.0 \
    -device pcie-root-port,id=pcie_extra_root_port_1,slot=6,chassis=6,addr=0x6,bus=pcie.0
19:28:44 INFO | Created qemu process with parent PID 18777
19:28:45 INFO | Connecting to monitor '<<class 'virttest.qemu_monitor.HumanMonitor'>> qmpmonitor1'
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'help set_link' 
19:28:45 DEBUG| Send command: help set_link
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Response to 'help set_link'
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1)    set_link name on|off -- change the link status of a network adapter
19:28:45 INFO | Connecting to monitor '<<class 'virttest.qemu_monitor.HumanMonitor'>> catch_monitor'
19:28:45 DEBUG| (monitor avocado-vt-vm1.catch_monitor) Sending command 'help set_link' 
19:28:45 DEBUG| Send command: help set_link
19:28:45 DEBUG| (monitor avocado-vt-vm1.catch_monitor) Response to 'help set_link'
19:28:45 DEBUG| (monitor avocado-vt-vm1.catch_monitor)    set_link name on|off -- change the link status of a network adapter
19:28:45 DEBUG| VM appears to be alive with PID 18785
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'info cpus' 
19:28:45 DEBUG| Send command: info cpus
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Response to 'info cpus'
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1)    * CPU #0: thread_id=18800
19:28:45 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1)      CPU #1: thread_id=18802
19:28:47 DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'cont' 
19:28:47 DEBUG| Send command: cont
19:28:47 INFO | Waiting for installation to finish. Timeout set to 7200 s (120 min)
19:28:47 DEBUG| Monitoring serial console log for completion message: /home/jenkins/workspace/ld-aarch64-gicv3-test/job-2019-08-18T12.53-ec07a5d/test-results/094-functional_git_RHEL-8_dvd io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads_-e630/serial-serial0-avocado-vt-vm1.log
21:28:47 WARNI| Timeout elapsed while waiting for install to finish 
21:28:47 DEBUG| Attempting to log into 'avocado-vt-vm1' (timeout 240s)
21:28:47 DEBUG| Retry verifying IP address (0.000015 secs)
21:29:49 DEBUG| Dropped the address cache of HWADDR (9a:30:63:fc:96:fc)
21:32:47 DEBUG| Attempting to log into 'avocado-vt-vm1' via serial console (timeout 240s)
21:33:01 INFO | [qemu output] (Process terminated with status 0)
21:33:08 WARNI| Error occur when update VM address cache: VM is dead
21:33:08 DEBUG| Sending command: true
21:33:08 INFO | Skipping log_useful_files #0: Shell process terminated while waiting for command to complete: 'true'    (status: 1,    output: 'Ncat: Broken pipe.\n')
21:33:08 ERROR| 
21:33:08 ERROR| Reproduced traceback from: /usr/lib/python3.6/site-packages/avocado_vt/test.py:449
21:33:08 ERROR| Traceback (most recent call last):
21:33:08 ERROR|   File "/var/lib/libvirt/images/avocado/avocado-vt/test-providers.d/downloads/io-github-autotest-qemu/generic/tests/unattended_install.py", line 25, in run
21:33:08 ERROR|     unattended_install.run(test, params, env)
21:33:08 ERROR|   File "/usr/lib/python3.6/site-packages/virttest/error_context.py", line 135, in new_fn
21:33:08 ERROR|     return fn(*args, **kwargs)
21:33:08 ERROR|   File "/usr/lib/python3.6/site-packages/virttest/tests/unattended_install.py", line 1444, in run
21:33:08 ERROR|     raise exceptions.TestFail("Timeout elapsed while waiting for install to "
21:33:08 ERROR| avocado.core.exceptions.TestFail: Timeout elapsed while waiting for install to finish
21:33:08 ERROR| 
21:33:09 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/usr/share/Modules/bin', '/bin', '/usr/bin', '/usr/libexec', '/sbin', '/usr/local/bin', '/usr/local/sbin', '/usr/sbin']
21:33:09 DEBUG| Checking image file /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2
21:33:09 DEBUG| Run qemu-img info command on /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2
21:33:09 INFO | Running '/home/jenkins/aarch64/qemu-master-build/bin/qemu-img info -U /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2 --output=human'
21:33:09 DEBUG| [stdout] image: /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2
21:33:09 DEBUG| [stdout] file format: qcow2
21:33:09 DEBUG| [stdout] virtual size: 10 GiB (10737418240 bytes)
21:33:09 INFO | Command '/home/jenkins/aarch64/qemu-master-build/bin/qemu-img info -U /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2 --output=human' finished with 0 after 0.22446656227111816s
21:33:09 DEBUG| [stdout] disk size: 2.73 GiB
21:33:09 DEBUG| [stdout] cluster_size: 65536
21:33:09 DEBUG| [stdout] Format specific information:
21:33:09 DEBUG| [stdout]     compat: 1.1
21:33:09 DEBUG| [stdout]     lazy refcounts: false
21:33:09 DEBUG| [stdout]     refcount bits: 16
21:33:09 DEBUG| [stdout]     corrupt: false
21:33:10 DEBUG| Copying /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2.backup -> /var/lib/libvirt/images/avocado/avocado-vt/images/rhel7devel-aarch64.qcow2
21:33:21 INFO | Running 'true'
21:33:21 INFO | Command 'true' finished with 0 after 0.0015797615051269531s
21:33:21 INFO | Running 'ps -o comm 1'
21:33:21 DEBUG| [stdout] COMMAND
21:33:21 INFO | Command 'ps -o comm 1' finished with 0 after 0.0528864860534668s
21:33:21 DEBUG| [stdout] systemd
21:33:21 ERROR| 
21:33:21 ERROR| Reproduced traceback from: /usr/local/lib/python3.6/site-packages/avocado/core/test.py:853
21:33:22 ERROR| Traceback (most recent call last):
21:33:22 ERROR|   File "/usr/lib/python3.6/site-packages/avocado_vt/test.py", line 312, in runTest
21:33:22 ERROR|     raise self.__status  # pylint: disable=E0702
21:33:22 ERROR|   File "/usr/lib/python3.6/site-packages/avocado_vt/test.py", line 263, in setUp
21:33:22 ERROR|     self._runTest()
21:33:22 ERROR|   File "/usr/lib/python3.6/site-packages/avocado_vt/test.py", line 438, in _runTest
21:33:22 ERROR|     run_func(self, params, env)
21:33:22 ERROR|   File "/var/lib/libvirt/images/avocado/avocado-vt/test-providers.d/downloads/io-github-autotest-qemu/generic/tests/unattended_install.py", line 25, in run
21:33:22 ERROR|     unattended_install.run(test, params, env)
21:33:22 ERROR|   File "/usr/lib/python3.6/site-packages/virttest/error_context.py", line 135, in new_fn
21:33:22 ERROR|     return fn(*args, **kwargs)
21:33:22 ERROR|   File "/usr/lib/python3.6/site-packages/virttest/tests/unattended_install.py", line 1444, in run
21:33:22 ERROR|     raise exceptions.TestFail("Timeout elapsed while waiting for install to "
21:33:22 ERROR| avocado.core.exceptions.TestFail: Timeout elapsed while waiting for install to finish
21:33:22 ERROR| 
21:33:22 DEBUG| Local variables:
21:33:54 DEBUG|  -> self <class 'avocado_vt.test.VirtTest'>: 094-functional/git/RHEL-8/dvd io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads;-e630
21:33:54 DEBUG| DATA (filename=output.expected) => NOT FOUND (data sources: variant, test, file)
21:33:54 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data sources: variant, test, file)
21:33:54 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data sources: variant, test, file)
21:33:54 ERROR| FAIL 094-functional/git/RHEL-8/dvd io-github-autotest-qemu.unattended_install.cdrom.extra_cdrom_ks.default_install.aio_threads;-e630 -> TestFail: Timeout elapsed while waiting for install to finish
21:33:54 INFO |