Problem with sharing serial port after upgrade from 5.2.28 to 6.0.X

[stagadet]

When I try to use a shared COM port (host device) on a guest running DOS 6.22 (using a legacy software for PLCs), on VirtualBox 6.0.8 (and also 6.0.6) I get errors like: Serial#0: Failed to change parameters to 2400,NONE,5,1 -> VERR_INVALID_PARAMETER and the software cannot communicate.

Everything works fine if I use VirtualBox 5.2.28 instead, with the same virtual machine.

The full log is attached.

[stagadet]

Full log showing the errors

[aeichner]

What is the supposed serial port setting your software is communicating with the device (baudrate, parity, etc.) The VBox.log contains failed attempts but ones which succeed are not logged so it might be possible that the errors are not relevant to the problem but there is something else going wrong. Can you post a VBox.log from a run with 5.2.28 please?

[Socratis]

Related discussion in the forums: ​https://forums.virtualbox.org/viewtopic.php?f=6&t=93132

Not much of a discussion, simply a Cc: I guess... ;)

[stagadet]

Unfortunately I don't know the settings the software I'm using needs to communicate, but using VirtualBox 5.2.28 no VERR_INVALID_PARAMETER error was issued.

I cannot post a VBox.log right now (no access to the hardware), but I will in the next few days.

For now, thank you for your interest.

[stagadet]

Log of version 5.2.28 not showing serial related errors

[stagadet]

I attached the log of VBox version 5.2.28 that is communicating fine and not showing any error.

If needed I can provide the VM (without the PLC you cannot communicate, but the errors are shown anyway). All the software is at least 20 years old, so I hope I'm not violating copyright laws.

[vitaliy]

I have a similar problem when using hardware flow control on a guest machine (I use write to raw file)

[Solartrand]

I have a similar issue with 6.0.12, I have an instrument connected via serial port (windows 10 host, xp sp1 64 client) to the virtual pc that communicates well on version 5.2.6, but with the new version I get erratic communication that works partly, up to a point where the communication fails and freezes over the software controlling the hardware (No error from the VM). I could not find something in the log related to this (that I can interpret anyways). Restarting the VM usually will make the communication works for a brief (random) amount of time before it freeze again.

Downgrading back to 5.2.6 fixed my issue. Since this is for a working instrument I can't debug as much as I want, but I wanted to share that there is still an issue.

[FelixG]

I have the same problem. Windows 10 host and Ecomstation guest. The software is old and does not show error, it tries the communication but it does not get it, apparently the serial port is not configured correctly. With VirtualBox version 6.0 and 6.1, the VBox.log shows:

Serial # 0: emulating 16550A (IOBase: 03f8 IRQ: 4)

Serial # 0: Failed to change parameters to 9600, NONE, 5.1 -> VERR_INVALID_PARAMETER

Serial # 0: Failed to change parameters to 9600, NONE, 5.1 -> VERR_INVALID_PARAMETER

With version 5.2.26 everything works correctly, and only shows:

Serial # 0: emulating 16550A

[FelixG]

All ok with v5.2.26

[FelixG]

Nok with v6.1.0

[FelixG]

My serial port is an FTDI model USB adapter.

I have monitored the serial communication and cannot find the problem. But I make the following observations:

With v5.2.34:

300, 9600, and 19200 Baud Rates appear.

IOCTL_SERIAL_SET_CHARS: Set special characters

· EOF = 0

· Error = 0

· Break = 0

· Event = 0

· XON = 0

· XOFF = 0

IOCTL_SERIAL_SET_HANDFLOW: Set handshake information

· Control lines = 0

· Flow control = SERIAL_XOFF_CONTINUE (0x80000000)

· Xon Limit = 5

· Xoff Limit = 5

With v6.1:

300, 429, 900, 9600 and 19200 Baud Rates appear. 429 is a very strange value!

IOCTL_SERIAL_SET_CHARS: Set special characters

· EOF = 0

· Error = 0

· Break = 0

· Event = 0

· XON = 0x11

· XOFF = 0x13

IOCTL_SERIAL_SET_HANDFLOW: Set handshake information

· Control lines = 0

· Flow control = SERIAL_RTS_CONTROL (0x40)

· Xon Limit = 2048

· Xoff Limit = 512

Perhaps in v6.1 there is a problem with the Xon / Xoff configuration.

[aeichner]

As I wasn't able to reproduce the issue so far we need some special logs from the serial port emulation. I prepared a testbuild which can be downloaded from here, look for the latest development testbuild (6.1.2+ state). In order to activate the tracing the VM needs some special config which can be added with

VBoxManage setextradata <VM name> "VBoxInternal/PDM/DriverTransformations/SerialTrace/AboveDriver"                         "Host Serial"
VBoxManage setextradata <VM name> "VBoxInternal/PDM/DriverTransformations/SerialTrace/AttachedDriver/Config/TraceFilePath" "<trace/log/file/path>"
VBoxManage setextradata <VM name> "VBoxInternal/PDM/DriverTransformations/SerialTrace/AttachedDriver/Driver"               "IfTrace"

<trace/log/file/path> needs to be substituted with a file path the user as write access to. <VM name> needs to be substituted with the VM name being traced. The current setup doesn't work if you have multiple serial ports configured which are using a host serial port device, so be sure to either disable all but one or leave them disconnected. Depending on the size the resulting logs can either be attached to this defect (they don't contain any data being transfered but only metadata about timings and parameters of certain function calls) or can be sent directly to Alexander (dot) Eichner (at) oracle (dot) com.

For the last reported issue (xon/xoff differences between 5.2 and 6.0/6.1) there already might be fix in the testbuild, so please try if this is still an issue and collect a log from the VM and your monitoring setup if possible for comparison, thanks!

[FelixG]

Nok log with testbuild 6.1.3 - test 1

[FelixG]

Nok log with testbuild 6.1.3 - test 2

[FelixG]

The log only works with v6.1.3.

With testbuild v5.2.35 an error message appears: The configured driver wasn't found. Either the necessary driver modules wasn't loaded, the name was misspelled, or it was a misconfiguration. (VERR_PDM_DRIVER_NOT_FOUND).

[aeichner]

Thanks for the logs! Yes the tracing code is in 6.1 only, do you still see the differences in your monitoring setup between 5.2 and 6.1 regarding Xon/Xoff handling?

[FelixG]

Sorry for waiting.

There is a moment at the beginning of the communication in which after a reading there is an immediate writing in v5.2 (Events 426-428 in OK_Capture.txt).

However, in v6.1 (Events 4844-4855 in NOK_Capture.txt) there is an exact 7-second wait and the program restarts the communication. It seems as if I don't see the end of the stream.

Comparing the captures of both versions I observe that in v6.1 many new events appear, while they do not exist in v5.2:

IOCTL: IOCTL_SERIAL_GET_COMMSTATUS (0x1b006c)

IOCTL_SERIAL_GET_COMMSTATUS: Retrieve COM status

· Errors = 0

· Hold reasons = 0

· In queue = 0

· Out queue = 0

· EOF received = false

· Wait for immediate = false

IOCTL_SERIAL_SET_WAIT_MASK: Set wait mask

· Wait Mask = SERIAL_EV_RXCHAR | SERIAL_EV_TXEMPTY | SERIAL_EV_CTS | SERIAL_EV_DSR | SERIAL_EV_RLSD | SERIAL_EV_BREAK | SERIAL_EV_ERR | SERIAL_EV_RING (0x1fd)

IOCTL_SERIAL_WAIT_ON_MASK: Wait for event

· Wait Mask = 0

IOCTL: IOCTL_SERIAL_SET_WAIT_MASK (0x1b0044)

.

As a last note, I observe in v5.2 (OK) and in v6.1.2-135663 (NOK):

IOCTL_SERIAL_SET_CHARS: Set special characters

· EOF = 0

· Error = 0

· Break = 0

· Event = 0

· XON = 0

· XOFF = 0

IOCTL: IOCTL_SERIAL_SET_CHARS (0x1b005c)

While in v6.1.3-135750 (NOK):

IOCTL_SERIAL_SET_CHARS: Set special characters

· EOF = 0

· Error = 0

· Break = 0

· Event = 0

· XON = 0x11

· XOFF = 0x13

IOCTL: IOCTL_SERIAL_SET_CHARS (0x1b005c)

.

I hope this data can help you find the problem.

[FelixG]

I have found the problem.

The driver I use, reads the received bytes one by one, and needs the interrupt to hold as long as bytes remain in the buffer.

In \VirtualBox-5.2.34\src\VBox\Devices\Serial\DevSerial.cpp, the routine "serial_update_irq" always updates the interrupt (PDMDevHlpISASetIrqNoWait / PDMDevHlpPCISetIrqNoWait).

When the RBR register is read, the "serial_ioport_read" routine calls "serial_update_irq", and therefore the interrupt is updated even if only one byte is read.

In \VirtualBox-6.1.x\src\VBox\Devices\Serial\UartCore.cpp, the routine "uartIrqUpdate" updates only the interrupt (pfnUartIrqReq) when it detects a change in the LSR register (line status) and IER register (interrupt status).

When the RBR register is read, the "uartR3ByteFetch" routine calls "uartIrqUpdate", but since there are no changes to LSR.DR, the interrupt is NOT updated when only one byte is read.

To fix it, I think the following change to the "uartIrqUpdate" routine is sufficient:

if (uRegIirNew != (pThis->uRegIir & UART_REG_IIR_CHANGED_MASK))

LogFlow((" Interrupt source changed from %#x -> %#x (IRQ %d -> %d)\n",

pThis->uRegIir, uRegIirNew, pThis->uRegIir == UART_REG_IIR_IP_NO_INT ? 0 : 1, uRegIirNew == UART_REG_IIR_IP_NO_INT ? 0 : 1));

else

LogFlow((" No change in interrupt source\n"));

if (uRegIirNew == UART_REG_IIR_IP_NO_INT)

pThisCC->pfnUartIrqReq(pDevIns, pThis, pThis->iLUN, 0);

else

pThisCC->pfnUartIrqReq(pDevIns, pThis, pThis->iLUN, 1);

[aeichner]

Thanks a lot for the diagnosis! I incorporated the patch into 6.1 and it will be available in the next maintenance release.

[FelixG]

I have encountered the same problem in a DOS software, and have been investigating.

In VirtualBox v5.2 when the RBR register is read, the routine "serial_ioport_read" 'case 0' (DevSerial.cpp) always resets the LSR_DR bit (and the LSR_BI,"break").

                ret = pThis->rbr;
                pThis->lsr &= ~(UART_LSR_DR | UART_LSR_BI);
            }
            serial_update_irq(pThis);

This causes the interrupt to go to 0, and then the "serialNotifyRead" routine sets the interrupt back to 1. If the operating system uses interrupt edges, this allows a new edge to be generated to indicate that there is pending data.

In VirtualBox v6.1.30, the routine "uartRegRbrDllRead" (UartCore.cpp) could be modified like this:

        if (pThis->uRegFcr & UART_REG_FCR_FIFO_EN)
        {
        ... (equal) ...
        }
        else
        {
#ifndef IN_RING3
            /*
             * Only go back to R3 if there is new data available for the FIFO
             * and we would clear the interrupt to fill it up again.
             */
            if (ASMAtomicReadU32(&pThis->cbAvailRdr) > 1)
            {
                rc = VINF_IOM_R3_IOPORT_READ;
            }
#endif
            if (rc == VINF_SUCCESS)
            {
                /* Reset the Break bit. */
                UART_REG_CLR(pThis->uRegLsr, UART_REG_LSR_BI);

                /* Reset the DR bit. This allows a new interrupt edge. */
                UART_REG_CLR(pThis->uRegLsr, UART_REG_LSR_DR);

                uartIrqUpdate(pDevIns, pThis, pThisCC);

                if (ASMAtomicReadU32(&pThis->cbAvailRdr) > 0)
                {
                    *puVal = pThis->uRegRbr;
                    Assert(pThis->cbAvailRdr);
                    uint32_t cbAvail = ASMAtomicDecU32(&pThis->cbAvailRdr);
                    if (cbAvail)
                    {
#ifndef IN_RING3
                        /* Restore state and go back to R3. */
                        ASMAtomicIncU32(&pThis->cbAvailRdr);
                        rc = VINF_IOM_R3_IOPORT_READ;
#else
                        /* Fetch new data and set the DR bit. */
                        uartR3DataFetch(pDevIns, pThis, pThisCC);
#endif
                    }
                }
                else
                {
                    /*
                     * This voids a rare situation where the RBR record is read
                     * and new data arrives at the same time.
                     */
                    *puVal = pThis->uRegRbr;
                }
            }
        }

Could you do a test build with this modification to see if it works?