OS-7215: bhyve uart broken for win2016 guest

Resolution

Fixed: A fix for this issue is checked into the tree and tested.
(Resolution Date: 2018-09-12T22:08:22.536Z)

Fix Versions

2018-09-13 Astronaut Mike Dexter (Release Date: 2018-09-13)

Related Links

Description

While trying to make use of NIC configuration via the metadata service painted into HVM guests via ttyb/COM2, it became apparent that the serial port was not functioning as expected. I removed the metadata service itself from the equation by assigning COM2 to a different listening socket on the host for debugging purposes. When connected with nc(1) in the host and putty in the guest, some data transfer across the port is possible, but there seem to be some missing notifications which lead to outbound (guest->host) data being delayed.

Comments

Comment by Max Bruning
Created at 2018-09-05T23:37:05.370Z
Also looks broken in ws2012r2.

 

Comment by Patrick Mooney
Created at 2018-09-05T23:46:47.321Z
During my investigation, the symptoms seem eerily similar to the broken behavior of the serial console observed for centos6 too.

Debugging efforts are ongoing.

Comment by Patrick Mooney
Created at 2018-09-06T21:22:18.289Z
I put together a dtrace script for tracing the internal state of a uart (COM2 specifically, in this case) in bhyve:
pid$target:a.out:lpc_uart_io_handler:entry
{
        this->port = (uint16_t)arg3;
        if (this->port >= 0x2f8 && this->port < 0x300) {
                self->p = 2; /* COM2 */
        } else if (this->port >= 0x3f8 && this->port < 0x400) {
                self->p = 1; /* COM1 */
        }

        /* optional: filter to COM2 */
        if (self->p == 1) {
                self->p = 0;
        }
}
pid$target:a.out:lpc_uart_io_handler:return
/self->p/
{
        self->p = 0;
        self->sc = (userland struct uart_softc *)0;
}

pid$target:a.out:uart_write:entry
/self->p/
{
        /* (struct uart_softc *sc, int offset, uint8_t value) */
        self->sc = (userland struct uart_softc *)arg0;
        self->o = (uint8_t)arg1;
        self->v = (uint8_t)arg2;

        /* The client worker thread does not know how sc maps to port */
        port_map[(uintptr_t)self->sc] = self->p;
}

pid$target:a.out:uart_read:entry
/self->p/
{
        /* (struct uart_softc *sc, int offset, uint8_t value) */
        self->sc = (userland struct uart_softc *)arg0;
        self->o = (uint8_t)arg1;
        self->v = (uint8_t)0;

        /* The client worker thread does not know how sc maps to port */
        port_map[(uintptr_t)self->sc] = self->p;
}

pid$target:a.out:uart_read:return
/self->p/
{
        self->v = (uint8_t)arg1;
}

pid$target:a.out:uart_write:entry,
pid$target:a.out:uart_read:entry,
pid$target:a.out:uart_write:return,
pid$target:a.out:uart_read:return
/self->p/
{
        printf("%lu %s:%s(%d:%01d, %02x)\t", (unsigned long)timestamp, probefunc, probename, self->p, self->o, self->v);
        printf("[ier:%02x lcr:%02x mcr:%02x lsr:%02x msr:%02x fcr:%02x scr:%02x dl:%04x]\n",
                self->sc->ier, self->sc->lcr, self->sc->mcr, self->sc->lsr, self->sc->msr, self->sc->fcr,
                self->sc->scr, ((uint16_t)self->sc->dlh << 8) | self->sc->dll);
}

pid$target:a.out:sockwrite:entry
{
        printf("%lu %s(%d, %02x)\n", (unsigned long)timestamp, probefunc, self->p, (uint8_t)arg1);
}


pid$target:a.out:uart_sock_drain:entry
/self->p = port_map[arg0]/
{
        self->drain = 1;
        printf("%lu %s:%s(%d)\n", (unsigned long)timestamp, probefunc, probename, self->p);
}

pid$target:a.out:uart_sock_drain:return
/self->drain/
{
        printf("%lu %s:%s(%d)\n", (unsigned long)timestamp, probefunc, probename, self->p);
        self->drain = 0;
}

pid$target:a.out:rxfifo_putchar:entry
/self->drain/
{
        printf("%lu %s:%s(%d, %02x)\n", (unsigned long)timestamp, probefunc, probename, self->p, (uint8_t)arg1);
}

pid$target:a.out:lpc_uart_intr_assert:entry,
pid$target:a.out:lpc_uart_intr_deassert:entry
/self->p/
{
        printf("%lu %s:%s(%d)\n", (unsigned long)timestamp, probefunc, probename, self->p);
}

I traced my win2016 instance from boot-up and then opened a PuTTY session on COM2. Once open, and with nc(1) connected to the appropriate socket in the host, I output a single 'a' character into the guest serial session. As had been observed previously, that character did not appear at the other end of the port. Once I send data back in the other direction (in this case, a simple newline), the 'a' sent from the guest appeared at the host. Output from the trace starts when the port is configured by PuTTY for 9600 baud:
27113834077377 uart_write:entry(2:3, 82)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:0060]
27113834082451 lpc_uart_intr_deassert:entry(2)
27113834086347 uart_write:return(2:3, 82)       [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:0060]
27113834108237 uart_write:entry(2:0, 0c)        [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:0060]
27113834112619 lpc_uart_intr_deassert:entry(2)
27113834116051 uart_write:return(2:0, 0c)       [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834137615 uart_write:entry(2:1, 00)        [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834141916 lpc_uart_intr_deassert:entry(2)
27113834145239 uart_write:return(2:1, 00)       [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834166649 uart_write:entry(2:3, 02)        [ier:0f lcr:82 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834171209 lpc_uart_intr_deassert:entry(2)
27113834174734 uart_write:return(2:3, 02)       [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834202971 uart_read:entry(2:4, 00) [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834207892 lpc_uart_intr_deassert:entry(2)
27113834211808 uart_read:return(2:4, 0b)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834235370 uart_write:entry(2:4, 0b)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834240000 lpc_uart_intr_deassert:entry(2)
27113834243469 uart_write:return(2:4, 0b)       [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834270605 uart_read:entry(2:4, 00) [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834275739 lpc_uart_intr_deassert:entry(2)
27113834279850 uart_read:return(2:4, 0b)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834303405 uart_write:entry(2:4, 0b)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834307898 lpc_uart_intr_deassert:entry(2)
27113834311361 uart_write:return(2:4, 0b)       [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834337818 uart_write:entry(2:3, 03)        [ier:0f lcr:02 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834342578 lpc_uart_intr_deassert:entry(2)
27113834346013 uart_write:return(2:3, 03)       [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834372881 uart_read:entry(2:6, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27113834377614 lpc_uart_intr_deassert:entry(2)
27113834381863 uart_read:return(2:6, a0)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777601071 uart_write:entry(2:1, 00)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777626945 lpc_uart_intr_deassert:entry(2)
27125777640238 uart_write:return(2:1, 00)       [ier:00 lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777707635 uart_write:entry(2:1, 0f)        [ier:00 lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777718536 lpc_uart_intr_deassert:entry(2)
27125777726979 uart_write:return(2:1, 0f)       [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432309871 uart_sock_drain:entry(2)
27129432350275 rxfifo_putchar:entry(2, 0a)
27129432370359 lpc_uart_intr_assert:entry(2)
27129432406219 uart_sock_drain:return(2)
27129432461938 uart_read:entry(2:2, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432485118 lpc_uart_intr_assert:entry(2)
27129432509345 uart_read:return(2:2, cc)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432575222 uart_read:entry(2:0, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432587156 lpc_uart_intr_deassert:entry(2)
27129432596849 uart_read:return(2:0, 0a)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432654937 uart_read:entry(2:5, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432665997 lpc_uart_intr_deassert:entry(2)
27129432675443 uart_read:return(2:5, 60)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432729567 uart_read:entry(2:2, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432740524 lpc_uart_intr_deassert:entry(2)
27129432752211 uart_read:return(2:2, c1)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432805505 uart_read:entry(2:5, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432816252 lpc_uart_intr_deassert:entry(2)
27129432828129 uart_read:return(2:5, 60)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432884732 uart_write:entry(2:0, 61)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129432898749 sockwrite(2, 61)
27129432933556 lpc_uart_intr_assert:entry(2)
27129432950203 uart_write:return(2:0, 61)       [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433006904 uart_read:entry(2:2, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433019621 lpc_uart_intr_deassert:entry(2)
27129433029364 uart_read:return(2:2, c2)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433084595 uart_read:entry(2:2, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433095435 lpc_uart_intr_deassert:entry(2)
27129433105078 uart_read:return(2:2, c1)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433158582 uart_read:entry(2:5, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433169422 lpc_uart_intr_deassert:entry(2)
27129433180736 uart_read:return(2:5, 60)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433241456 uart_read:entry(2:2, 00) [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27129433252466 lpc_uart_intr_deassert:entry(2)
27129433261893 uart_read:return(2:2, c1)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]


Comment by Patrick Mooney
Created at 2018-09-06T21:28:46.166Z
In that trace, the lack of an attempted write to the COM2 data register (2:0 in this bespoke notation) was definitely questionable. I suspected that the OS might be waiting for some condition/interrupt before sending data. The fact that bhyve has the THRE bit permanently wired on seemed relevant to the problem as well. Working back from the timestamps, we do see activity from the guest when the 'a' was entered in PuTTY:
27125777601071 uart_write:entry(2:1, 00)        [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777626945 lpc_uart_intr_deassert:entry(2)
27125777640238 uart_write:return(2:1, 00)       [ier:00 lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777707635 uart_write:entry(2:1, 0f)        [ier:00 lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
27125777718536 lpc_uart_intr_deassert:entry(2)
27125777726979 uart_write:return(2:1, 0f)       [ier:0f lcr:03 mcr:0b lsr:60 msr:a0 fcr:c1 scr:00 dl:000c]
It is essentially disabling and re-enabling interrupts on the chip. One feasible possibility was that it expected an interrupt for the THRE condition. Cross-checking with qemu/KVM showed that kind of behavior.

Comment by Patrick Mooney
Created at 2018-09-12T20:59:17.947Z
With this change, win2016 is able to access the metadata service via COM2 as desired. I also fired up Linux and FreeBSD guests to see if their serial port behavior was changed. Both were still able to query metadata as before.

Comment by Jira Bot
Created at 2018-09-12T22:06:43.374Z
illumos-joyent commit 2bf1a940afbd1382faff159e7c93c72779ca10f4 (branch master, by Patrick Mooney)

OS-7215 bhyve uart broken for win2016 guest
Reviewed by: Joshua M. Clulow <jmc@joyent.com>
Reviewed by: Hans Rosenfeld <hans.rosenfeld@joyent.com>
Approved by: Hans Rosenfeld <hans.rosenfeld@joyent.com>