Hang on Helios guest restart. #559
Description
I have a Helios machine running inside Propolis. Issued a reboot after a pkg update in the guest and things seem to be stuck.
Here is the log from propolis-server.
03:19:45.480Z INFO propolis-server: allocating from reservoir (131008MiB) for guest memory
03:19:45.480Z INFO propolis-server: Starting server...
03:19:45.480Z INFO propolis-server: listening
local_addr = [::]:15043
03:19:46.462Z INFO propolis-server: accepted connection
local_addr = [::]:15043
remote_addr = [::1]:43956
03:19:46.463Z INFO propolis-server: new DNS resolver
addresses = [[::1:0:0:0:1]:53, [::2:0:0:0:1]:53, [::3:0:0:0:1]:53, [::4:0:0:0:1]:53, [::5:0:0:0:1]:53]
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
03:19:51.465Z WARN propolis-server: Failed to determine Nexus: endpoint no record found for Query { name: Name("_nexus._tcp.control-plane.oxide.internal."), query_type: SRV, query_class: IN }
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
03:19:51.466Z INFO propolis-server: initializing new VM
bootrom = /var/ovmf/OVMF_CODE.fd
properties = InstanceProperties {\n id: e892f8ef-7015-401b-80b1-de821fee7970,\n name: "g3",\n description: "a falcon vm",\n image_id: 00000000-0000-0000-0000-000000000000,\n bootrom_id: 00000000-0000-0000-0000-000000000000,\n memory: 4096,\n vcpus: 4,\n}
spec = V0(\n InstanceSpecV0 {\n devices: DeviceSpecV0 {\n board: Board {\n cpus: 4,\n memory_mb: 4096,\n chipset: I440Fx(\n I440Fx {\n enable_pcie: false,\n },\n ),\n },\n storage_devices: {\n "block0": VirtioDisk(\n VirtioDisk {\n backend_name: "main_disk",\n pci_path: PciPath {\n bus: 0,\n device: 4,\n function: 0,\n },\n },\n ),\n },\n network_devices: {\n "vnic-0.10.0": VirtioNic(\n VirtioNic {\n backend_name: "vnic-0.10.0-backend",\n pci_path: PciPath {\n bus: 0,\n device: 10,\n function: 0,\n },\n },\n ),\n "vnic-0.8.0": VirtioNic(\n VirtioNic {\n backend_name: "vnic-0.8.0-backend",\n pci_path: PciPath {\n bus: 0,\n device: 8,\n function: 0,\n },\n },\n ),\n "vnic-0.9.0": VirtioNic(\n VirtioNic {\n backend_name: "vnic-0.9.0-backend",\n pci_path: PciPath {\n bus: 0,\n device: 9,\n function: 0,\n },\n },\n ),\n },\n serial_ports: {\n "com3": SerialPort {\n num: Com3,\n },\n "com1": SerialPort {\n num: Com1,\n },\n "com2": SerialPort {\n num: Com2,\n },\n },\n pci_pci_bridges: {},\n softnpu_pci_port: Some(\n SoftNpuPciPort {\n pci_path: PciPath {\n bus: 0,\n device: 7,\n function: 0,\n },\n },\n ),\n softnpu_ports: {\n "port4": SoftNpuPort {\n name: "port4",\n backend_name: "a4x2_g3_sn_vnic7",\n },\n "port5": SoftNpuPort {\n name: "port5",\n backend_name: "a4x2_g3_sn_vnic8",\n },\n "port1": SoftNpuPort {\n name: "port1",\n backend_name: "a4x2_g3_sn_vnic1",\n },\n "port3": SoftNpuPort {\n name: "port3",\n backend_name: "a4x2_g3_sn_vnic4",\n },\n "port2": SoftNpuPort {\n name: "port2",\n backend_name: "a4x2_g3_sn_vnic2",\n },\n "port0": SoftNpuPort {\n name: "port0",\n backend_name: "a4x2_g3_sn_vnic0",\n },\n },\n softnpu_p9: Some(\n SoftNpuP9 {\n pci_path: PciPath {\n bus: 0,\n device: 6,\n function: 0,\n },\n },\n ),\n p9fs: Some(\n P9fs {\n source: "/home/ry/src/testbed/a4x2/cargo-bay/g3",\n target: "/opt/cargo-bay",\n chunk_size: 65536,\n pci_path: PciPath {\n bus: 0,\n device: 5,\n function: 0,\n },\n },\n ),\n },\n backends: BackendSpecV0 {\n storage_backends: {\n "main_disk": File(\n FileStorageBackend {\n path: "/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3",\n readonly: false,\n },\n ),\n },\n network_backends: {\n "a4x2_g3_sn_vnic1": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic1",\n },\n ),\n "vnic-0.8.0-backend": Virtio(\n VirtioNetworkBackend {\n vnic_name: "a4x2_g3_vn_vnic3",\n },\n ),\n "a4x2_g3_sn_vnic4": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic4",\n },\n ),\n "a4x2_g3_sn_vnic7": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic7",\n },\n ),\n "a4x2_g3_sn_vnic0": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic0",\n },\n ),\n "vnic-0.10.0-backend": Virtio(\n VirtioNetworkBackend {\n vnic_name: "a4x2_g3_vn_vnic6",\n },\n ),\n "a4x2_g3_sn_vnic8": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic8",\n },\n ),\n "a4x2_g3_sn_vnic2": Dlpi(\n DlpiNetworkBackend {\n vnic_name: "a4x2_g3_sn_vnic2",\n },\n ),\n "vnic-0.9.0-backend": Virtio(\n VirtioNetworkBackend {\n vnic_name: "a4x2_g3_vn_vnic4",\n },\n ),\n },\n },\n },\n)
use_reservoir = true
03:19:51.473Z INFO propolis-server: Creating vNIC vnic-0.10.0
03:19:51.573Z INFO propolis-server: Creating vNIC vnic-0.8.0
03:19:51.711Z INFO propolis-server: Creating vNIC vnic-0.9.0
03:19:51.784Z INFO propolis-server: softnpu: data links [
"a4x2_g3_sn_vnic0",
"a4x2_g3_sn_vnic1",
"a4x2_g3_sn_vnic2",
"a4x2_g3_sn_vnic4",
"a4x2_g3_sn_vnic7",
"a4x2_g3_sn_vnic8",
]
03:19:51.787Z INFO propolis-server: Creating storage device block0 with properties VirtioDisk(VirtioDisk { backend_name: "main_disk", pci_path: PciPath { bus: 0, device: 4, function: 0 } })
03:19:51.787Z INFO propolis-server: Creating file disk backend
path = /dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
03:19:51.828Z INFO propolis-server (vcpu_tasks): Starting vCPU thread
vcpu = 0
03:19:51.828Z INFO propolis-server (vcpu_tasks): Starting vCPU thread
vcpu = 1
03:19:51.828Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 0
03:19:51.828Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 1
03:19:51.828Z INFO propolis-server (vcpu_tasks): Starting vCPU thread
vcpu = 2
03:19:51.828Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 2
03:19:51.828Z INFO propolis-server (vcpu_tasks): Starting vCPU thread
vcpu = 3
03:19:51.828Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 3
03:19:51.828Z INFO propolis-server (vm_state_worker): State worker launched
03:19:51.828Z INFO propolis-server (serial task): Entered serial task
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
03:19:51.828Z INFO propolis-server: request completed
latency_us = 5365415
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
response_code = 201
uri = /instance
03:19:51.830Z INFO propolis-server (vm_controller): Requested state Run via API
03:19:51.830Z INFO propolis-server (external_request_queue): Queuing external request
disposition = Enqueue
request = Start
03:19:51.830Z INFO propolis-server (vm_state_worker): State worker handling event
event = External(Start)
03:19:51.830Z INFO propolis-server (vm_state_worker): Starting instance
reason = ExplicitRequest
03:19:51.830Z INFO propolis-server: request completed
latency_us = 198
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = bd667f9e-aaf4-4081-84d3-3033f48a7b02
response_code = 204
uri = /instance/state
03:19:51.830Z INFO propolis-server (vm_controller): Resetting vCPU 0
03:19:51.830Z INFO propolis-server (vm_controller): Resetting BSP vCPU 0
03:19:51.830Z INFO propolis-server (vm_controller): Resetting vCPU 1
03:19:51.830Z INFO propolis-server (vm_controller): Resetting vCPU 2
03:19:51.830Z INFO propolis-server (vm_controller): Resetting vCPU 3
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-atpic
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-atpit
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-hpet
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-ioapic
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-rtc
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to bhyve-vcpu-0
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to bhyve-vcpu-1
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to bhyve-vcpu-2
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to bhyve-vcpu-3
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to chipset-i440fx
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-piix4-hb
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-piix3-lpc
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-piix3-pm
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-bhyve-pmtimer
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-uart-com3
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-uart-com1
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-uart-com2
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-ps2ctrl
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to qemu-lpc-debug
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-viona-0.10.0
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-viona-0.8.0
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-viona-0.9.0
03:19:51.830Z INFO propolis-server (vm_controller): Sending startup complete to lpc-uart-softnpu-uart
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-9pfs-softnpu-p9fs
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to softnpu
03:19:51.831Z INFO propolis-server: softnpu: running management handler
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 0
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 1
03:19:51.831Z INFO propolis-server: management handler thread started
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 0
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 2
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 1
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 3
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 4
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 2
03:19:51.831Z INFO propolis-server: starting ingress packet handler for port 5
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 3
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 4
03:19:51.831Z INFO propolis-server: ingress packet handler is running for port 5
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-softnpu-port-0.7.0
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-9pfs
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to pci-virtio-block-0.4.0
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to qemu-fwcfg
03:19:51.831Z INFO propolis-server (vm_controller): Sending startup complete to qemu-ramfb
03:19:51.831Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 1
03:19:51.831Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 0
03:19:51.831Z INFO propolis-server (vm_state_worker): State worker handled event
outcome = Continue
03:19:51.831Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 2
03:19:51.831Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 3
03:19:51.831Z INFO propolis-server: accepted connection
local_addr = [::]:15043
remote_addr = [::1]:34916
03:19:51.832Z INFO propolis-server: request completed
latency_us = 129
local_addr = [::]:15043
method = GET
remote_addr = [::1]:34916
req_id = ca2f025a-76e1-4dd9-a873-95dae8efcb10
response_code = 101
uri = /instance/serial
03:19:52.015Z INFO propolis-server (ramfb): ramfb change
config = Config { addr: 3197108224, fourcc: 875713112, flags: 0, width: 800, height: 600, stride: 3200 }
state = valid
03:19:52.015Z INFO propolis-server (ramfb): notifying
03:19:52.015Z INFO propolis-server (vnc-server): pixel format set to fourcc=0x34325258
03:21:27.983Z WARN propolis-server: read: exact: "/home/ry/src/testbed/a4x2/cargo-bay/g3/omicron/out/dendrite-stub/bin": Os { code: 21, kind: IsADirectory, 03:21:34.899Z INFO propolis-server (serial task): Removing closed serial connection 0.
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
03:21:34.899Z WARN propolis-server (serial task): Failed while closing stream 0: Connection closed normally
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:35:49.326Z INFO propolis-server: accepted connection
local_addr = [::]:15043
remote_addr = [::ffff:127.0.0.1]:48587
16:35:49.326Z INFO propolis-server: request completed
latency_us = 83
local_addr = [::]:15043
method = GET
remote_addr = [::ffff:127.0.0.1]:48587
req_id = 35bb382c-d0d7-457e-9b48-644408b26de3
response_code = 101
uri = /instance/serial
16:36:00.307Z WARN propolis-server: attach fid in use: 1
16:47:00.460Z INFO propolis-server (vm_state_worker): State worker handling event
event = Guest(VcpuSuspendTripleFault(1))
16:47:00.460Z INFO propolis-server (vm_state_worker): Resetting due to triple fault on vCPU 1
16:47:00.460Z INFO propolis-server (vm_state_worker): Resetting instance
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-atpic
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-atpit
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-hpet
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-ioapic
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-rtc
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-1
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-2
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-3
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to chipset-i440fx
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-piix4-hb
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-piix3-lpc
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-piix3-pm
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-pmtimer
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com3
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com1
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com2
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-ps2ctrl
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to qemu-lpc-debug
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.10.0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.8.0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.9.0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-softnpu-uart
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to softnpu
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-softnpu-port-0.7.0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-9pfs
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-block-0.4.0
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to qemu-fwcfg
16:47:00.460Z INFO propolis-server (vm_controller): Sending pause request to qemu-ramfb
16:47:00.460Z INFO propolis-server (vm_controller): Waiting for entities to pause
16:47:00.460Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-atpic
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-atpit
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-hpet
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-ioapic
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-rtc
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-1
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-2
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-3
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix4-hb
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix3-lpc
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-pmtimer
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix3-pm
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity chipset-i440fx
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com3
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com1
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com2
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-ps2ctrl
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity qemu-lpc-debug
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.10.0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.8.0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.9.0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-softnpu-uart
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-9pfs-softnpu-p9fs
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity softnpu
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-softnpu-port-0.7.0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-9pfs
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-block-0.4.0
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity qemu-fwcfg
16:47:00.461Z INFO propolis-server (vm_controller): Got paused future from entity qemu-ramfb
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-atpic
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-atpit
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-hpet
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-ioapic
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-rtc
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-1
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-2
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-3
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to chipset-i440fx
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-piix4-hb
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-piix3-lpc
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-piix3-pm
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-pmtimer
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com3
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com1
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com2
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-ps2ctrl
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to qemu-lpc-debug
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.10.0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.8.0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.9.0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-softnpu-uart
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to softnpu
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-softnpu-port-0.7.0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-9pfs
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-block-0.4.0
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to qemu-fwcfg
16:47:00.461Z INFO propolis-server (vm_controller): Sending reset request to qemu-ramfb
16:47:00.462Z INFO propolis-server (vm_controller): Resetting vCPU 0
16:47:00.462Z INFO propolis-server (vm_controller): Resetting BSP vCPU 0
16:47:00.462Z INFO propolis-server (vm_controller): Resetting vCPU 1
16:47:00.462Z INFO propolis-server (vm_controller): Resetting vCPU 2
16:47:00.462Z INFO propolis-server (vm_controller): Resetting vCPU 3
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-atpic
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-atpit
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-hpet
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-ioapic
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-rtc
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-1
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-2
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-3
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to chipset-i440fx
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-piix4-hb
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-piix3-lpc
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-piix3-pm
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-pmtimer
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com3
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com1
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com2
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-ps2ctrl
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to qemu-lpc-debug
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.10.0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.8.0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.9.0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-softnpu-uart
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to softnpu
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-softnpu-port-0.7.0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-9pfs
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-block-0.4.0
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to qemu-fwcfg
16:47:00.462Z INFO propolis-server (vm_controller): Sending resume request to qemu-ramfb
16:47:00.462Z INFO propolis-server (vm_state_worker): State worker handled event
outcome = Continue
16:47:00.462Z INFO propolis-server (vm_state_worker): State worker handling event
event = Guest(VcpuSuspendTripleFault(0))
16:47:00.462Z INFO propolis-server (vm_state_worker): Resetting due to triple fault on vCPU 0
16:47:00.462Z INFO propolis-server (vm_state_worker): Resetting instance
16:47:00.462Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 0
16:47:00.462Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 1
16:47:00.462Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 2
16:47:00.462Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 3
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-atpic
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-atpit
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-hpet
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-ioapic
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-rtc
16:47:00.462Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-1
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-2
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to bhyve-vcpu-3
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to chipset-i440fx
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-piix4-hb
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-piix3-lpc
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-piix3-pm
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-bhyve-pmtimer
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com3
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com1
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-com2
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-ps2ctrl
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to qemu-lpc-debug
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.10.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.8.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-viona-0.9.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to lpc-uart-softnpu-uart
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to softnpu
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-softnpu-port-0.7.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-9pfs
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to pci-virtio-block-0.4.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to qemu-fwcfg
16:47:00.463Z INFO propolis-server (vm_controller): Sending pause request to qemu-ramfb
16:47:00.463Z INFO propolis-server (vm_controller): Waiting for entities to pause
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-atpic
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-atpit
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-hpet
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-ioapic
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-rtc
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-1
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-2
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity bhyve-vcpu-3
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix4-hb
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix3-lpc
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-bhyve-pmtimer
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-piix3-pm
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity chipset-i440fx
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com3
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com1
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-com2
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-ps2ctrl
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity qemu-lpc-debug
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.10.0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.8.0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-viona-0.9.0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity lpc-uart-softnpu-uart
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-9pfs-softnpu-p9fs
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity softnpu
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-softnpu-port-0.7.0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-9pfs
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity pci-virtio-block-0.4.0
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity qemu-fwcfg
16:47:00.463Z INFO propolis-server (vm_controller): Got paused future from entity qemu-ramfb
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-atpic
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-atpit
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-hpet
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-ioapic
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-rtc
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-1
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-2
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to bhyve-vcpu-3
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to chipset-i440fx
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-piix4-hb
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-piix3-lpc
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-piix3-pm
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-bhyve-pmtimer
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com3
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com1
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-com2
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-ps2ctrl
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to qemu-lpc-debug
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.10.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.8.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-viona-0.9.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to lpc-uart-softnpu-uart
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to softnpu
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-softnpu-port-0.7.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-9pfs
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to pci-virtio-block-0.4.0
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to qemu-fwcfg
16:47:00.463Z INFO propolis-server (vm_controller): Sending reset request to qemu-ramfb
16:47:00.463Z INFO propolis-server (vm_controller): Resetting vCPU 0
16:47:00.463Z INFO propolis-server (vm_controller): Resetting BSP vCPU 0
16:47:00.463Z INFO propolis-server (vm_controller): Resetting vCPU 1
16:47:00.463Z INFO propolis-server (vm_controller): Resetting vCPU 2
16:47:00.463Z INFO propolis-server (vm_controller): Resetting vCPU 3
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-atpic
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-atpit
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-hpet
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-ioapic
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-rtc
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-0
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-1
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-2
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to bhyve-vcpu-3
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to chipset-i440fx
16:47:00.463Z INFO propolis-server (vm_controller): Sending resume request to pci-piix4-hb
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-piix3-lpc
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-piix3-pm
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-bhyve-pmtimer
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com3
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com1
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-com2
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-ps2ctrl
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to qemu-lpc-debug
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.10.0
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.8.0
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-viona-0.9.0
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to lpc-uart-softnpu-uart
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-9pfs-softnpu-p9fs
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to softnpu
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-softnpu-port-0.7.0
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-9pfs
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to pci-virtio-block-0.4.0
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to block-file-/dev/zvol/rdsk/rpool/falcon/topo/a4x2/g3
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to qemu-fwcfg
16:47:00.464Z INFO propolis-server (vm_controller): Sending resume request to qemu-ramfb
16:47:00.464Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 0
16:47:00.464Z INFO propolis-server (vm_state_worker): State worker handled event
outcome = Continue
16:47:00.464Z INFO propolis-server (vm_state_worker): State worker handling event
event = Guest(VcpuSuspendTripleFault(3))
16:47:00.464Z INFO propolis-server (vm_state_worker): Resetting due to triple fault on vCPU 3
16:47:00.464Z INFO propolis-server (vm_state_worker): Resetting instance
16:47:00.464Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 2
16:47:00.464Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 3
16:47:00.464Z INFO propolis-server (vcpu_tasks): vCPU released from hold
vcpu = 1
16:47:00.464Z INFO propolis-server (vcpu_tasks): vCPU paused
vcpu = 0
16:51:03.252Z INFO propolis-server (serial task): Removing closed serial connection 1.
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:51:03.253Z WARN propolis-server (serial task): Failed while closing stream 1: Connection closed normally
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:51:05.031Z INFO propolis-server: accepted connection
local_addr = [::]:15043
remote_addr = [::ffff:127.0.0.1]:57693
16:51:05.031Z INFO propolis-server: request completed
latency_us = 69
local_addr = [::]:15043
method = GET
remote_addr = [::ffff:127.0.0.1]:57693
req_id = f696b729-85d5-4ddf-b3a9-8a851fd237be
response_code = 101
uri = /instance/serial
16:53:25.489Z INFO propolis-server (serial task): Removing closed serial connection 2.
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:53:25.490Z WARN propolis-server (serial task): Failed while closing stream 2: Connection closed normally
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:55:03.465Z INFO propolis-server: accepted connection
local_addr = [::]:15043
remote_addr = [::ffff:127.0.0.1]:55625
16:55:03.465Z INFO propolis-server: request completed
latency_us = 73
local_addr = [::]:15043
method = GET
remote_addr = [::ffff:127.0.0.1]:55625
req_id = 05a0d722-af18-4137-9840-909121a22eeb
response_code = 101
uri = /instance/serial
16:59:15.705Z INFO propolis-server (serial task): Removing closed serial connection 3.
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
16:59:15.705Z WARN propolis-server (serial task): Failed while closing stream 3: Connection closed normally
local_addr = [::]:15043
method = PUT
remote_addr = [::1]:43956
req_id = 11b57ba2-925d-4b4c-9208-154102775f74
uri = /instance
Metadata
Metadata
Assignees
Labels
No labels