sometimes qemu start failed (or serial port interrupted) when the kernel initialize serial device

[gnawux]

This issue listed two cases:

• The first case is described in container init was failed to kill if signal comes before container init executed hyperstart#285 and fixed in double confirm the process has already been started hyperstart#286

'TestSuite.TestSendContainerSignal' failed to end as attached.

In the test matrix, it's high probability there are one job (and only one) out of five jobs failed. And if > restart the job, it will pass.

log-toolong.txt

• The second case is qemu stop/interrupted when guest initializing serial device.

And the remain disscussion of this thread is about the second case.

[gnawux]

This is confirmed that not related with this issue

I0317 16:49:45.829586   23145 json.go:521] get hyperstart API version error: send ctl channel error, the hyperstart might have closed

[gnawux]

I0317 10:34:55.297563   23218 decommission.go:544] Pod[busybox] got vm exit event
I0317 10:34:55.297575   23218 decommission.go:592] Pod[busybox] umount all containers and volumes, release IP addresses
I0317 10:34:55.297588   23218 etchosts.go:97] cleanupHosts /var/lib/hyper/hosts/busybox, /var/lib/hyper/hosts/busybox/hosts
I0317 10:34:55.297616   23218 etchosts.go:101] cannot find /var/lib/hyper/hosts/busybox/hosts
I0317 10:34:55.297708   23218 decommission.go:572] Pod[busybox] sandbox info removed from db
I0317 10:34:55.297719   23218 decommission.go:577] Pod[busybox] tag pod as stopped
I0317 10:34:55.297726   23218 decommission.go:584] Pod[busybox] pod stopped
I0317 10:34:58.021414   23218 json.go:521] get hyperstart API version error: send ctl channel error, the hyperstart might have closed
E0317 10:35:19.764693   23218 hypervisor.go:49] SB[vm-QeEPbljMVQ] watch hyperstart timeout

another case, on TestSuite.TestCreateAndStartPod
log-toolong-1.txt

[gnawux]

another similar one on TestSuite.TestRenameContainer
log-toolong-2.txt

[gnawux]

I think it's more or less related with the hyperstart protocol handling, at least, it should not stall here if the protocol state machine transits to an illegal state. @laijs could you check this one?

now it will fail fast, however, the problem has not been solved

[gnawux]

looks the serial port disconnected while the kernel init the serial device...

I0316 16:48:30.441463   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0316 16:48:30.447921   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0316 16:48:30.448010   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0316 16:48:30.453452   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0316 16:48:30.453663   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0316 16:48:30.458682   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
I0316 16:48:30.459030   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver

Based on the console message, Interrupt here, do you have any ideas @bergwolf @gao-feng ?

I0316 16:48:30.465716   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0316 16:48:30.489577   23090 vm_console.go:46] SB[vm-CRDiGlKuWp] [CNL] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A

[gnawux]

the #554 is the same problem.

log-test-stopped.txt

[gao-feng]

not quite sure if this bug is fixed by golang/go@5bcdd63

[gnawux]

@gao-feng go 1.8 only?

[bergwolf]

we would never read with zero length buffer:

        buf := make([]byte, 512)
        res := []byte{}
        for read < needRead {
                want := needRead - read
                if want > 512 {
                        want = 512
                }
                nr, err := conn.Read(buf[:want])

[gnawux]

looks this commit is included in both 1.7 and 1.8.