System.Runtime.InteropServices.COMException

[james-70]

Hi Jason, I have been using your library for a project we are developing, and it has been very useful - Thanks. I have run into the following problem when communicating with a device for an extended period.

The setup is as follows: Embedded Micro (NXP Cortex) USB based COM port connected to a tablet form factor PC Windows USB driver listed as LPC USB VCom Port Tablet PC is running Win10 IoT Enterprise LTSC 2019 (Pro x64) .NET 4.8 SerialPortStream 2.3.1 (latest via Nuget) Visual Studio 2019

Continuous data being sent in both directions. Serial port setup: 115200,N,8,1 After an extended period of time, I see the following exception, and serial comms stop:

Exception thrown: 'System.Runtime.InteropServices.COMException' in mscorlib.dll The semaphore timeout period has expired. (Exception from HRESULT: 0x80070079)

I have enabled tracing, this is the tail, but nothing obvious is reported (I can supply more logfile if useful):

IO.Ports.SerialPortStream Verbose: 0 : COM3: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM3: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: DoReadEvent: ReadFile(1392, 1801077291737, 369991) == False
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessReadEvent: 140 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessReadEvent: End=678585; Bytes=140
IO.Ports.SerialPortStream Verbose: 0 : COM3: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM3: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: DoReadEvent: ReadFile(1392, 1801077291877, 369851) == False
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: DoWriteEvent: WriteFile(1392, 1801077704391, 4, ...) == False
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessWaitCommEvent: EV_RXCHAR, EV_TXEMPTY, EV_RX80FULL
IO.Ports.SerialPortStream Verbose: 0 : COM3: CommEvent: EV_TXEMPTY, EV_RX80FULL
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessWriteEvent: 4 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: DoWriteEvent: WriteFile(1392, 1801077704395, 4, ...) == False
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessReadEvent: 138 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessReadEvent: End=678725; Bytes=138
IO.Ports.SerialPortStream Verbose: 0 : COM3: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM3: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: DoReadEvent: ReadFile(1392, 1801077292015, 369713) == False
IO.Ports.SerialPortStream Verbose: 0 : COM3: SerialThread: ProcessReadEvent: 127 

Here is a snippet of my code:

        public void ConnectUSBSerialPort(string VID = vid, string PID = pid)
        {
            List<string> myPortList = FindComPortNamesInRegistry(VID, PID);

            if (myPortList.Count == 1)
            {
                Console.WriteLine(myPortList.First<string>());
                sps = new SerialPortStream(myPortList.First<string>(), baud, data, parity, stopbits);
                sps.ReceivedBytesThreshold = 1;
                sps.DataReceived += sps_DataReceived;
                sps.ErrorReceived += sps_ErrorReceived;
                sps.ReadTimeout = 5;   // Set the read timeouts to react to characters
                sps.Open();
                // Setup a connection timer that fires when no data is received for 500ms
                _commswatchdogtimer.Interval = commsWatchDogTimeout;
                _commswatchdogtimer.Start();
            }
        }

        private void sps_DataReceived(object s, SerialDataReceivedEventArgs e)
        {
            _commswatchdogtimer.Interval = commsWatchDogTimeout;
            byte[] data = new byte[sps.BytesToRead];
            sps.Read(data, 0, data.Length);            
            data.ToList().ForEach(b => receivedData.Enqueue(b));
            DispatchData();
        }

Any thoughts as to whether it could be driver related (older version of Win10) or a bug in SerialPortStream ?

[james-70]

I have also confirmed the same exception occurs on a regular desktop version of Windows 10 Pro 20H2

[jcurl]

Hi, I'm glad you can reproduce the problem, as we'll need to capture logs that show the error. In the logs you've shown, it shows that 127 bytes was read and returned (the word bytes was cut off on the last line).

Can you provide the full details of the exception? It should show the stack trace which can help to identify where the problem occurred, or provide the complete set of logs. There are a few places where Marshal.ThrowExceptionForHR is called, the stack trace will help me identify which API called failed. Most of the time there's a Trace of type Error (or Warning) before raising the exception also.

[james-70]

Hi Jason, I built the library from source rather than using the nuget package, and was able to find where the exception was being thrown. I'm attaching a screenshot, which hopefully shows everything you need to know:

Here is the relevant error from the logfile (had to continue the debug to flush the error to the log):

IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094880734, 640578) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoWriteEvent: WriteFile(1596, 2799095603292, 3, ...) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessWriteEvent: 3 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoWriteEvent: WriteFile(1596, 2799095603295, 5, ...) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: 10 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: End=407998; Bytes=10
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094880744, 640568) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: 115 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: End=408008; Bytes=115
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094880859, 640453) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: 116 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: End=408123; Bytes=116
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094880975, 640337) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: 107 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: End=408239; Bytes=107
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094881082, 640230) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: 148 bytes
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessReadEvent: End=408346; Bytes=148
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_RXCHAR
IO.Ports.SerialPortStream Verbose: 0 : COM10: HandleEvent: Chars; NoError; NoChange;
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(1596, 2799094881230, 640082) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessWaitCommEvent: EV_RXCHAR, EV_TXEMPTY, EV_RX80FULL
IO.Ports.SerialPortStream Verbose: 0 : COM10: CommEvent: EV_TXEMPTY, EV_RX80FULL
IO.Ports.SerialPortStream Error: 0 : COM10: SerialThread: Overlapped WriteFile() error 121 bytes 0
IO.Ports.SerialPortStream Error: 0 : COM10: SerialThread: Died from The semaphore timeout period has expired. (Exception from HRESULT: 0x80070079)
IO.Ports.SerialPortStream Verbose: 0 : COM10: OverlappedIO: Stopping Thread
IO.Ports.SerialPortStream Verbose: 0 : COM10: OverlappedIO: Waiting for Thread
IO.Ports.SerialPortStream Verbose: 0 : COM10: OverlappedIO: Thread Stopped
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: DoReadEvent: ReadFile(2508, 2799096006184, 1048576) == False
IO.Ports.SerialPortStream Verbose: 0 : COM10: SerialThread: ProcessWaitCommEvent: EV_RXCHAR, EV_RX80FULL

[jcurl]

Thanks for the log and the screenshot. Looking at the MS documentation for GetOverlappedResult there is no meaning for error code 121 (See MSDN). We'll have to experiment, because MS driver code is closed source, we can't see what causes this error. I've seen this in previous reports mostly to do with bluetooth and RFComm drivers.

I'm guessing you tried to write some data, and the data was never sent? Are you able to confirm if your device was able to receive the data that you expected? The logs show you tried to write 5 bytes and this failed by the driver with error 121.

I could see if I can implement a retry, that if it occurs say 5 times for this specific error, we abort. I assume no data was sent as the error code indicated 0 bytes. But a retry could very well result in a protocol failure on the receiving device.

[james-70]

Hi Jason, Sorry for the slow response. We have since found that the exceptions being thrown can be worked around in our application code. Thanks for your efforts looking into this issue, and providing a very useful serial library.

[jcurl]

Thanks for following up. To understand better the root cause, can you describe what you found?

[james-70]

Hi Jason, The main changes were to the legacy (read: not ideal) serial protocol being used in our product. The exceptions are still being thrown, but we turned the sensitivity down in the debugger, and they don't seem to percolate up to our code.

[jcurl]

Just wanted to check this again and did some research. It's very much likely a driver problem.

On stackoverflow, there's this comment:

It is a low-level Windows error, ERROR_SEM_TIMEOUT, error code 121. Highly specific to code that uses a semaphore. The .NET SerialPort classes don't use a semaphore anywhere. The Bluetooth driver you are using that emulates the serial port surely is using one, it is a common synchronization object used in native code. Having these kind of problems with buggy drivers is not unusual.