Skip to content

ReverseDebugging_ppc64 avocado test is not working reliably

Host environment

  • Operating system: CentOS 8 container in the gitlab-CI
  • Architecture: x86
  • QEMU flavor: qemu-system-ppc64
  • QEMU version: commit af9264da (close to 8.2-rc1)
  • QEMU command line: make check-avocado

Emulated/Virtualized environment

  • Operating system: see tests/avocado/reverse_debugging.py
  • Architecture: ppc64

Description of problem

The tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv test is sometimes failing in the gitlab-CI. Looking at the logs, it seems like QEMU is dying early here, so this might be a real bug and not only an issue with the test. Full debug.log from the failing job:

08:28:31 DEBUG| PARAMS (key=arch, path=*, default=ppc64) => 'ppc64'
08:28:31 DEBUG| PARAMS (key=cpu, path=*, default=None) => None
08:28:31 DEBUG| PARAMS (key=qemu_bin, path=*, default=./qemu-system-ppc64) => './qemu-system-ppc64'
08:28:31 DEBUG| PARAMS (key=machine, path=*, default=powernv) => 'powernv'
08:28:31 INFO | creating qcow2 image for VM snapshots
08:28:31 INFO | Running '/builds/thuth/qemu/build/qemu-img create -f qcow2 /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2 128M'
08:28:31 DEBUG| [stdout] Formatting '/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=134217728 lazy_refcounts=off refcount_bits=16
08:28:31 INFO | Command '/builds/thuth/qemu/build/qemu-img create -f qcow2 /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2 128M' finished with 0 after 0.024550681999926383s
08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" created
08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" temp_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/qemu-machine-uq5k4nlc
08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" log_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv
08:28:31 INFO | recording the execution...
08:28:31 DEBUG| Using selector: EpollSelector
08:28:31 DEBUG| Registering <qemu.qmp.events.EventListener object at 0x7ff6584bae50>.
08:28:31 DEBUG| VM launch command: './qemu-system-ppc64 -display none -vga none -chardev socket,id=mon,fd=5 -mon chardev=mon,mode=control -machine powernv -chardev socket,id=console,fd=19 -serial chardev:console -icount shift=7,rr=record,rrfile=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin,rrsnapshot=init -net none -drive file=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2,if=none'
08:28:31 DEBUG| Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'.
08:28:31 DEBUG| Connecting with existing socket: fd=12, family=<AddressFamily.AF_UNIX: 1>, type=<SocketKind.SOCK_STREAM: 1>
08:28:31 DEBUG| Connected.
08:28:31 DEBUG| Awaiting greeting ...
08:28:31 DEBUG| <-- {
  "QMP": {
    "version": {
      "qemu": {
        "micro": 90,
        "minor": 1,
        "major": 8
      },
      "package": "v5.2.0-26508-gaf9264da80"
    },
    "capabilities": [
      "oob"
    ]
  }
}
08:28:31 DEBUG| Negotiating capabilities ...
08:28:31 DEBUG| --> {
  "execute": "qmp_capabilities",
  "arguments": {
    "enable": [
      "oob"
    ]
  }
}
08:28:31 DEBUG| <-- {
  "return": {}
}
08:28:31 DEBUG| Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
08:28:31 DEBUG| Opening console socket
08:28:31 DEBUG| --> {
  "execute": "query-replay"
}
08:28:31 DEBUG| <-- {
  "return": {
    "icount": 5521801,
    "mode": "record",
    "filename": "/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin"
  }
}
08:28:31 DEBUG| --> {
  "execute": "query-replay"
}
08:28:31 DEBUG| [    0.230392217,5] OPAL v7.0 starting...
08:28:31 DEBUG| [    0.230674939,7] initial console log level: memory 7, driver 5
08:28:31 DEBUG| [    0.231048494,6] CPU: P9 generation processor (max 4 threads/core)
08:28:31 DEBUG| [    0.231412547,7] CPU: Boot CPU PIR is 0x0000 PVR is 0x004e1202
08:28:31 DEBUG| [    0.231857798,7] OPAL table
08:28:31 DEBUG| <-- {
  "return": {
    "icount": 5655658,
    "mode": "record",
    "filename": "/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin"
  }
}
08:28:31 DEBUG| Shutting down VM appliance; timeout=30
08:28:31 DEBUG| Attempting graceful termination
08:28:31 DEBUG| Closing console socket
08:28:31 DEBUG| Politely asking QEMU to terminate
08:28:31 DEBUG| --> {
  "execute": "quit"
}
08:28:31 DEBUG| <-- {
  "return": {}
}
08:28:31 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 453159
  },
  "event": "SHUTDOWN",
  "data": {
    "guest": false,
    "reason": "host-qmp-quit"
  }
}
08:28:31 DEBUG| disconnect() called.
08:28:31 DEBUG| Transitioning from 'Runstate.RUNNING' to 'Runstate.DISCONNECTING'.
08:28:31 DEBUG| Scheduling disconnect.
08:28:31 DEBUG| Draining the outbound queue ...
08:28:31 DEBUG| Flushing the StreamWriter ...
08:28:31 DEBUG| Cancelling writer task.
08:28:31 DEBUG| Cancelling reader task.
08:28:31 DEBUG| Waiting for tasks to complete ...
08:28:31 DEBUG| Task.Writer: cancelled.
08:28:31 DEBUG| Task.Writer: exiting.
08:28:31 DEBUG| Task.Reader: cancelled.
08:28:31 DEBUG| Task.Reader: exiting.
08:28:31 DEBUG| Closing StreamWriter.
08:28:31 DEBUG| Waiting for StreamWriter to close ...
08:28:31 DEBUG| StreamWriter closed.
08:28:31 DEBUG| Disconnected.
08:28:31 DEBUG| QMP Disconnected.
08:28:31 DEBUG| Transitioning from 'Runstate.DISCONNECTING' to 'Runstate.IDLE'.
08:28:31 DEBUG| Waiting (timeout=30) for QEMU process (pid=1580) to terminate
08:28:31 DEBUG| Cleaning up after VM process
08:28:31 INFO | recorded log with 5655658+ steps
08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" created
08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" temp_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/qemu-machine-i11yz6dd
08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" log_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv
08:28:31 INFO | replaying the execution...
08:28:31 DEBUG| Registering <qemu.qmp.events.EventListener object at 0x7ff655d27700>.
08:28:31 DEBUG| VM launch command: './qemu-system-ppc64 -display none -vga none -chardev socket,id=mon,fd=5 -mon chardev=mon,mode=control -machine powernv -chardev socket,id=console,fd=19 -serial chardev:console -gdb tcp::21192 -S -icount shift=7,rr=replay,rrfile=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin,rrsnapshot=init -net none -drive file=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2,if=none'
08:28:31 DEBUG| Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'.
08:28:31 DEBUG| Connecting with existing socket: fd=12, family=<AddressFamily.AF_UNIX: 1>, type=<SocketKind.SOCK_STREAM: 1>
08:28:31 DEBUG| Connected.
08:28:31 DEBUG| Awaiting greeting ...
08:28:31 DEBUG| <-- {
  "QMP": {
    "version": {
      "qemu": {
        "micro": 90,
        "minor": 1,
        "major": 8
      },
      "package": "v5.2.0-26508-gaf9264da80"
    },
    "capabilities": [
      "oob"
    ]
  }
}
08:28:31 DEBUG| Negotiating capabilities ...
08:28:31 DEBUG| --> {
  "execute": "qmp_capabilities",
  "arguments": {
    "enable": [
      "oob"
    ]
  }
}
08:28:31 DEBUG| <-- {
  "return": {}
}
08:28:31 DEBUG| Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
08:28:31 DEBUG| Opening console socket
08:28:31 INFO | connecting to gdbstub
08:28:31 INFO | stepping forward
08:28:31 INFO | saving position 10
08:28:31 INFO | saving position 14
08:28:31 INFO | saving position 40
08:28:31 INFO | saving position 44
08:28:31 INFO | saving position 3008
08:28:31 INFO | saving position 300c
08:28:31 INFO | saving position 3010
08:28:31 INFO | saving position 3014
08:28:31 INFO | saving position 3018
08:28:31 INFO | saving position 301c
08:28:31 INFO | stepping backward
08:28:31 INFO | found position 301c
08:28:31 INFO | found position 3018
08:28:31 INFO | found position 3014
08:28:31 INFO | found position 3010
08:28:31 INFO | found position 300c
08:28:31 INFO | found position 3008
08:28:31 INFO | found position 44
08:28:31 INFO | found position 40
08:28:32 INFO | found position 14
08:28:32 INFO | found position 10
08:28:32 INFO | stepping forward
08:28:32 INFO | found position 10
08:28:32 INFO | found position 14
08:28:32 INFO | found position 40
08:28:32 INFO | found position 44
08:28:32 INFO | found position 3008
08:28:32 INFO | found position 300c
08:28:32 INFO | found position 3010
08:28:32 INFO | found position 3014
08:28:32 INFO | found position 3018
08:28:32 INFO | found position 301c
08:28:32 INFO | setting breakpoints
08:28:32 INFO | continuing execution
08:28:32 DEBUG| --> {
  "execute": "replay-break",
  "arguments": {
    "icount": 5655657
  }
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 630400
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 630738
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 630965
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 631155
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 631438
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 631653
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 631935
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 632127
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 632380
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 632593
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 632858
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 633051
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 633316
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 633517
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 633775
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 633973
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 634247
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 634437
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 634707
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 634910
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 681146
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 681795
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 722346
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 723103
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 764757
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 765468
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 806932
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 807686
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 849868
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 850664
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 892036
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 892734
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 934846
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 935520
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 976442
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555311,
    "microseconds": 977155
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 29287
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 30093
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 74012
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 74271
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 74873
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 75471
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 75800
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 75987
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 76239
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 76423
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 76666
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 76861
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 77106
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 77321
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 77564
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 77760
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 77987
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 78176
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 78408
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 78598
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 78846
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 79033
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 79267
  },
  "event": "RESUME"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 79451
  },
  "event": "STOP"
}
08:28:32 DEBUG| <-- {
  "return": {}
}
08:28:32 DEBUG| [    0.230392217,5] OPAL v7.0 starting...
08:28:32 DEBUG| [    0.230674939,7] initial console log level: memory 7, driver 5
08:28:32 DEBUG| [    0.231048494,6] CPU: P9 generation processor (max 4 threads/core)
08:28:32 DEBUG| [
08:28:32 DEBUG| [    0.231412547,7] CPU: Boot CPU PIR is 0x0000 PVR is 0x004e1202
08:28:32 DEBUG| [
08:28:32 ERROR| 
08:28:32 ERROR| Reproduced traceback from: /builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py:770
08:28:32 ERROR| Traceback (most recent call last):
08:28:32 ERROR|   File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 262, in test_ppc64_powernv
08:28:32 ERROR|     self.reverse_debugging()
08:28:32 ERROR|   File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 178, in reverse_debugging
08:28:32 ERROR|     g.cmd(b'c')
08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 783, in cmd
08:28:32 ERROR|     response_payload = self.decode(result)
08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 738, in decode
08:28:32 ERROR|     raise InvalidPacketError
08:28:32 ERROR| avocado.utils.gdb.InvalidPacketError
08:28:32 ERROR| 
08:28:32 DEBUG| Local variables:
08:28:32 DEBUG|  -> self <class 'reverse_debugging.ReverseDebugging_ppc64'>: 79-tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv
08:28:32 DEBUG| Shutting down VM appliance; timeout=30
08:28:32 DEBUG| Attempting graceful termination
08:28:32 DEBUG| Closing console socket
08:28:32 DEBUG| Politely asking QEMU to terminate
08:28:32 DEBUG| --> {
  "execute": "quit"
}
08:28:32 DEBUG| <-- {
  "timestamp": {
    "seconds": 1700555312,
    "microseconds": 86122
  },
  "event": "RESUME"
}
08:28:32 ERROR| Task.Reader: BrokenPipeError: [Errno 32] Broken pipe
08:28:32 DEBUG| Task.Reader: failure:
  | Traceback (most recent call last):
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever
  |     await async_fn()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message
  |     msg = await self._recv()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv
  |     message = await self._do_recv()
  |   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv
  |     msg_bytes = await self._readline()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline
  |     msg_bytes = await self._reader.readline()
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline
  |     line = await self.readuntil(sep)
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil
  |     await self._wait_for_data('readuntil')
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data
  |     await self._waiter
  |   File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write
  |     n = self._sock.send(data)
  | BrokenPipeError: [Errno 32] Broken pipe

08:28:32 DEBUG| Transitioning from 'Runstate.RUNNING' to 'Runstate.DISCONNECTING'.
08:28:32 DEBUG| Scheduling disconnect.
08:28:32 DEBUG| Task.Reader: exiting.
08:28:32 DEBUG| Cancelling writer task.
08:28:32 DEBUG| Waiting for tasks to complete ...
08:28:32 DEBUG| Task.Writer: cancelled.
08:28:32 DEBUG| Task.Writer: exiting.
08:28:32 DEBUG| Waiting for StreamWriter to close ...
08:28:32 DEBUG| Discarding Exception from wait_closed:
  | Traceback (most recent call last):
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream
  |     await wait_closed(self._writer)
  |   File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
  |     await writer.wait_closed()
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed
  |     await self._protocol._get_close_waiter(self)
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever
  |     await async_fn()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message
  |     msg = await self._recv()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv
  |     message = await self._do_recv()
  |   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv
  |     msg_bytes = await self._readline()
  |   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline
  |     msg_bytes = await self._reader.readline()
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline
  |     line = await self.readuntil(sep)
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil
  |     await self._wait_for_data('readuntil')
  |   File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data
  |     await self._waiter
  |   File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write
  |     n = self._sock.send(data)
  | BrokenPipeError: [Errno 32] Broken pipe

08:28:32 DEBUG| StreamWriter closed.
08:28:32 DEBUG| Disconnected.
08:28:32 DEBUG| Cancelling pending executions
08:28:32 DEBUG| Cancelling execution 'None'
08:28:32 DEBUG| QMP Disconnected.
08:28:32 DEBUG| disconnect() called.
08:28:32 DEBUG| Transitioning from 'Runstate.DISCONNECTING' to 'Runstate.IDLE'.
08:28:32 DEBUG| Graceful shutdown failed
Traceback (most recent call last):
  File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 574, in _soft_shutdown
    self.qmp('quit')
  File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 705, in qmp
    ret = self._qmp.cmd_raw(cmd, args=qmp_args)
  File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
    return self.cmd_obj(qmp_cmd)
  File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
    self._sync(
  File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
    return self._aloop.run_until_complete(
  File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for
    return await fut
  File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
    return await self._execute(msg, assign_id=assign_id)
  File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
    return await self._reply(exec_id)
  File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
    raise result
qemu.qmp.qmp_client.ExecInterruptedError: Disconnected

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 605, in _do_shutdown
    self._soft_shutdown(timeout)
  File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 577, in _soft_shutdown
    self._close_qmp_connection()
  File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 495, in _close_qmp_connection
    self._qmp.close()
  File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 281, in close
    self._sync(
  File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
    return self._aloop.run_until_complete(
  File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for
    return await fut
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
    await self._wait_disconnect()
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect
    await all_defined_tasks  # Raise Exceptions from the bottom half.
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream
    await wait_closed(self._writer)
  File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
    await writer.wait_closed()
  File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed
    await self._protocol._get_close_waiter(self)
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever
    await async_fn()
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message
    msg = await self._recv()
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv
    message = await self._do_recv()
  File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv
    msg_bytes = await self._readline()
  File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline
    msg_bytes = await self._reader.readline()
  File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline
    line = await self.readuntil(sep)
  File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil
    await self._wait_for_data('readuntil')
  File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data
    await self._waiter
  File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write
    n = self._sock.send(data)
BrokenPipeError: [Errno 32] Broken pipe
08:28:32 DEBUG| Falling back to hard shutdown
08:28:32 DEBUG| Performing hard shutdown
08:28:32 DEBUG| Cleaning up after VM process
08:28:32 ERROR| 
08:28:32 ERROR| Reproduced traceback from: /builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py:796
08:28:32 ERROR| Traceback (most recent call last):
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 574, in _soft_shutdown
08:28:32 ERROR|     self.qmp('quit')
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 705, in qmp
08:28:32 ERROR|     ret = self._qmp.cmd_raw(cmd, args=qmp_args)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
08:28:32 ERROR|     return self.cmd_obj(qmp_cmd)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
08:28:32 ERROR|     self._sync(
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
08:28:32 ERROR|     return self._aloop.run_until_complete(
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete
08:28:32 ERROR|     return future.result()
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for
08:28:32 ERROR|     return await fut
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
08:28:32 ERROR|     return await self._execute(msg, assign_id=assign_id)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
08:28:32 ERROR|     return await self._reply(exec_id)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
08:28:32 ERROR|     raise result
08:28:32 ERROR| qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
08:28:32 ERROR| 
08:28:32 ERROR| During handling of the above exception, another exception occurred:
08:28:32 ERROR| 
08:28:32 ERROR| Traceback (most recent call last):
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 605, in _do_shutdown
08:28:32 ERROR|     self._soft_shutdown(timeout)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 577, in _soft_shutdown
08:28:32 ERROR|     self._close_qmp_connection()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 495, in _close_qmp_connection
08:28:32 ERROR|     self._qmp.close()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 281, in close
08:28:32 ERROR|     self._sync(
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
08:28:32 ERROR|     return self._aloop.run_until_complete(
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete
08:28:32 ERROR|     return future.result()
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for
08:28:32 ERROR|     return await fut
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
08:28:32 ERROR|     await self._wait_disconnect()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect
08:28:32 ERROR|     await all_defined_tasks  # Raise Exceptions from the bottom half.
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream
08:28:32 ERROR|     await wait_closed(self._writer)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
08:28:32 ERROR|     await writer.wait_closed()
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed
08:28:32 ERROR|     await self._protocol._get_close_waiter(self)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever
08:28:32 ERROR|     await async_fn()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message
08:28:32 ERROR|     msg = await self._recv()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv
08:28:32 ERROR|     message = await self._do_recv()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv
08:28:32 ERROR|     msg_bytes = await self._readline()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline
08:28:32 ERROR|     msg_bytes = await self._reader.readline()
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline
08:28:32 ERROR|     line = await self.readuntil(sep)
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil
08:28:32 ERROR|     await self._wait_for_data('readuntil')
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data
08:28:32 ERROR|     await self._waiter
08:28:32 ERROR|   File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write
08:28:32 ERROR|     n = self._sock.send(data)
08:28:32 ERROR| BrokenPipeError: [Errno 32] Broken pipe
08:28:32 ERROR| 
08:28:32 ERROR| The above exception was the direct cause of the following exception:
08:28:32 ERROR| 
08:28:32 ERROR| Traceback (most recent call last):
08:28:32 ERROR|   File "/builds/thuth/qemu/build/tests/avocado/avocado_qemu/__init__.py", line 384, in tearDown
08:28:32 ERROR|     vm.shutdown()
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 642, in shutdown
08:28:32 ERROR|     self._do_shutdown(timeout)
08:28:32 ERROR|   File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 612, in _do_shutdown
08:28:32 ERROR|     raise AbnormalShutdown("Could not perform graceful shutdown") \
08:28:32 ERROR| qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
08:28:32 ERROR| 
08:28:32 DEBUG| DATA (filename=output.expected) => NOT FOUND (data sources: variant, test, file)
08:28:32 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data sources: variant, test, file)
08:28:32 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data sources: variant, test, file)
08:28:32 ERROR| Traceback (most recent call last):

08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py", line 858, in _run_avocado
    raise test_exception

08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py", line 765, in _run_avocado
    testMethod()

08:28:32 ERROR|   File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 262, in test_ppc64_powernv
    self.reverse_debugging()

08:28:32 ERROR|   File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 178, in reverse_debugging
    g.cmd(b'c')

08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 783, in cmd
    response_payload = self.decode(result)

08:28:32 ERROR|   File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 738, in decode
    raise InvalidPacketError

08:28:32 ERROR| avocado.utils.gdb.InvalidPacketError

08:28:32 ERROR| ERROR 79-tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv -> InvalidPacketError: 
08:28:32 INFO |
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information