Rodemfr / MicronetToNMEA

A NMEA 0183 converter for Raymarine's wireless instruments ... and much more !
GNU General Public License v3.0
20 stars 7 forks source link

Buffer overflows when sending multiple NMEA sentences to MTN #58

Closed tvr256 closed 1 year ago

tvr256 commented 1 year ago

I'm connecting my MTN via USB to a Raspberry Pi running SignalK/OpenPlotter. The Raspberry also has a GPS dongle attached, and SignalK forwards all the GPS NMEA sentences to MTN and onwards to Micronet.

Unfortunately SignalK is reporting buffer overflows when sending multiple sentences to MTN. I'm not an expert, but it looks to me like MTN isn't processing the incoming messages fast enough.

The logs show that once per second, SignalK sends a burst of 8 sentences (RMC, VTG, GGA, GSA, GSV, GSV, GSV, GLL) in a 37ms period. The first 6 sentences are processed correctly by MTN, and the last 2 are dropped:

I've tried both 9600bps and 115200bps, and also tried running the Teensy 4.0 at 24mHz and 600mHz, but it doesn't make a difference.

Nov 25 14:14:27 2022-11-25T14:14:27.912Z signalk:streams:serialport Writing:$GPRMC,141428.00,A,5115.60758,N,00040.68381,W,0.028,,251122,,,A*69

Nov 25 14:14:27 2022-11-25T14:14:27.923Z signalk:streams:serialport Writing:$GPVTG,,T,,M,0.028,N,0.052,K,A*2E

Nov 25 14:14:27 2022-11-25T14:14:27.927Z signalk:streams:serialport Writing:$GPGGA,141428.00,5115.60758,N,00040.68381,W,1,08,1.32,61.2,M,46.2,M,,*75

Nov 25 14:14:27 2022-11-25T14:14:27.933Z signalk:streams:serialport Writing:$GPGSA,A,3,30,19,13,14,17,05,24,15,,,,,2.03,1.32,1.55*0F

Nov 25 14:14:27 2022-11-25T14:14:27.937Z signalk:streams:serialport Writing:$GPGSV,3,1,11,05,14,192,30,10,15,325,,12,04,204,,13,57,125,42*72

Nov 25 14:14:27 2022-11-25T14:14:27.943Z signalk:streams:serialport Writing:$GPGSV,3,2,11,14,36,056,20,15,77,209,27,17,21,093,36,19,09,125,33*7E

Nov 25 14:14:27 2022-11-25T14:14:27.945Z signalk:streams:serialport Buffer overflow, not writing:$GPGSV,3,3,11,23,35,298,21,24,45,265,27,30,10,077,16*48

Nov 25 14:14:27 2022-11-25T14:14:27.949Z signalk:streams:serialport Buffer overflow, not writing:$GPGLL,5115.60758,N,00040.68381,W,141428.00,A,A*7D

Nov 25 14:14:28 2022-11-25T14:14:28.915Z signalk:streams:serialport Writing:$GPRMC,141429.00,A,5115.60752,N,00040.68378,W,0.063,,251122,,,A*6B

Nov 25 14:14:28 2022-11-25T14:14:28.924Z signalk:streams:serialport Writing:$GPVTG,,T,,M,0.063,N,0.117,K,A*21

Nov 25 14:14:28 2022-11-25T14:14:28.928Z signalk:streams:serialport Writing:$GPGGA,141429.00,5115.60752,N,00040.68378,W,1,08,1.32,61.3,M,46.2,M,,*79

Nov 25 14:14:28 2022-11-25T14:14:28.933Z signalk:streams:serialport Writing:$GPGSA,A,3,30,19,13,14,17,05,24,15,,,,,2.03,1.32,1.55*0F

Nov 25 14:14:28 2022-11-25T14:14:28.937Z signalk:streams:serialport Writing:$GPGSV,3,1,11,05,14,192,30,10,15,325,,12,04,204,,13,57,125,42*72

Nov 25 14:14:28 2022-11-25T14:14:28.940Z signalk:streams:serialport Writing:$GPGSV,3,2,11,14,36,056,20,15,77,209,28,17,21,093,36,19,09,125,33*71

Nov 25 14:14:28 2022-11-25T14:14:28.941Z signalk:streams:serialport Buffer overflow, not writing:$GPGSV,3,3,11,23,35,298,21,24,45,265,27,30,10,077,17*49

Nov 25 14:14:28 2022-11-25T14:14:28.945Z signalk:streams:serialport Buffer overflow, not writing:$GPGLL,5115.60752,N,00040.68378,W,141429.00,A,A*70

Nov 25 14:14:29 2022-11-25T14:14:29.916Z signalk:streams:serialport Writing:$GPRMC,141430.00,A,5115.60738,N,00040.68370,W,0.112,,251122,,,A*60

Nov 25 14:14:29 2022-11-25T14:14:29.925Z signalk:streams:serialport Writing:$GPVTG,,T,,M,0.112,N,0.207,K,A*24

Nov 25 14:14:29 2022-11-25T14:14:29.929Z signalk:streams:serialport Writing:$GPGGA,141430.00,5115.60738,N,00040.68370,W,1,08,1.32,61.5,M,46.2,M,,*73

Nov 25 14:14:29 2022-11-25T14:14:29.935Z signalk:streams:serialport Writing:$GPGSA,A,3,30,19,13,14,17,05,24,15,,,,,2.03,1.32,1.55*0F

Nov 25 14:14:29 2022-11-25T14:14:29.937Z signalk:streams:serialport Writing:$GPGSV,3,1,11,05,14,192,30,10,15,325,,12,04,204,,13,57,125,42*72

Nov 25 14:14:29 2022-11-25T14:14:29.939Z signalk:streams:serialport Writing:$GPGSV,3,2,11,14,36,056,21,15,77,209,29,17,21,093,37,19,09,125,34*77

Nov 25 14:14:29 2022-11-25T14:14:29.941Z signalk:streams:serialport Buffer overflow, not writing:$GPGSV,3,3,11,23,35,298,20,24,45,265,27,30,10,077,17*48

Nov 25 14:14:29 2022-11-25T14:14:29.944Z signalk:streams:serialport Buffer overflow, not writing:$GPGLL,5115.60738,N,00040.68370,W,141430.00,A,A*7C

Nov 25 14:14:30 2022-11-25T14:14:30.917Z signalk:streams:serialport Writing:$GPRMC,141431.00,A,5115.60730,N,00040.68365,W,0.161,,251122,,,A*69

Nov 25 14:14:30 2022-11-25T14:14:30.924Z signalk:streams:serialport Writing:$GPVTG,,T,,M,0.161,N,0.299,K,A*27

Nov 25 14:14:30 2022-11-25T14:14:30.930Z signalk:streams:serialport Writing:$GPGGA,141431.00,5115.60730,N,00040.68365,W,1,08,1.32,61.7,M,46.2,M,,*7C

Nov 25 14:14:30 2022-11-25T14:14:30.935Z signalk:streams:serialport Writing:$GPGSA,A,3,30,19,13,14,17,05,24,15,,,,,2.03,1.32,1.55*0F

Nov 25 14:14:30 2022-11-25T14:14:30.937Z signalk:streams:serialport Writing:$GPGSV,3,1,11,05,14,192,30,10,15,325,,12,04,204,,13,57,125,42*72

Nov 25 14:14:30 2022-11-25T14:14:30.939Z signalk:streams:serialport Writing:$GPGSV,3,2,11,14,36,056,21,15,77,209,29,17,21,093,37,19,09,125,34*77

Nov 25 14:14:30 2022-11-25T14:14:30.941Z signalk:streams:serialport Buffer overflow, not writing:$GPGSV,3,3,11,23,35,298,19,24,45,265,27,30,10,077,18*4D

Nov 25 14:14:30 2022-11-25T14:14:30.944Z signalk:streams:serialport Buffer overflow, not writing:$GPGLL,5115.60730,N,00040.68365,W,141431.00,A,A*71
Rodemfr commented 1 year ago

I got a similar problem with my config : OpenCPN is receiving all its data from a NMEA simulator (position, wind, speed, depth, etc.), forwarding everything to bluetooth/serial, received by HC-06 and then forwarded to MTN via a UART connection. I concluded that the problem was not because of MTN because MTN receives data from a RS232 connection without flow control. So, it is impossible for HC-06 to know if MTN as properly processed data. If the transmission chain reports overflow, it is either HC-06 which receive more data than its output can cop-up with (115000 bps in my case), either the PC itself because the bluetooth/serial driver more data than it can handle on its given bitrate. What is your configuration ? How is MTN receiving NMEA data : wired NMEA or USB-NMEA ?

Rodemfr commented 1 year ago

at 115200 bauds, you can receive around 11 bytes per millisecond. So in 37ms, you can send a bit more than 400 bytes. It might be that the data burst from signal K overflows a serial buffer somewhere.

Rodemfr commented 1 year ago

You could try to increase the baudrate above 115200 to check the theory. Teensy can handle higher baudrates.

tvr256 commented 1 year ago

I'm connecting via USB. I'll try increasing the data rate above 115200 and see if it helps.

Rodemfr commented 1 year ago

It might be different with USB-Serial on Teensy where a control flow might be implemented. Let me know the result.

tvr256 commented 1 year ago

I've tried with baudrate set to 921600, but I'm still seeing the same error. Individual sentences are sent correctly, but a burst of multiple sentences causes a buffer overflow:

Nov 28 11:46:10 2022-11-28T11:46:10.191Z signalk:streams:serialport Writing:$INHDG,256,,,,*51

Nov 28 11:46:10 2022-11-28T11:46:10.636Z signalk:streams:serialport Writing:$INVHW,,T,256,M,,N,,K*63

Nov 28 11:46:10 2022-11-28T11:46:10.676Z signalk:streams:serialport Writing:$INMWV,7.0,R,0.0,N,A*3d

Nov 28 11:46:10 2022-11-28T11:46:10.681Z signalk:streams:serialport Writing:$INVHW,,T,256,M,,N,,K*63

Nov 28 11:46:10 2022-11-28T11:46:10.685Z signalk:streams:serialport Writing:$INVHW,,T,256,M,,N,,K*63

Nov 28 11:46:10 2022-11-28T11:46:10.696Z signalk:streams:serialport Writing:$INHDG,256,,,,*51

Nov 28 11:46:10 2022-11-28T11:46:10.916Z signalk:streams:serialport Writing:$GPRMC,114611.00,A,5115.60183,N,00040.67878,W,0.154,,281122,,,A*64

Nov 28 11:46:10 2022-11-28T11:46:10.924Z signalk:streams:serialport Writing:$GPVTG,,T,,M,0.154,N,0.284,K,A*2D

Nov 28 11:46:10 2022-11-28T11:46:10.928Z signalk:streams:serialport Writing:$GPGGA,114611.00,5115.60183,N,00040.67878,W,1,05,2.79,93.0,M,46.2,M,,*71

Nov 28 11:46:10 2022-11-28T11:46:10.931Z signalk:streams:serialport Writing:$GPGSA,A,3,30,13,20,14,05,,,,,,,,7.75,2.79,7.23*0E

Nov 28 11:46:10 2022-11-28T11:46:10.932Z signalk:streams:serialport Writing:$GPGSV,3,1,12,02,23,278,,05,66,249,31,07,31,058,,08,05,045,*7A

Nov 28 11:46:10 2022-11-28T11:46:10.933Z signalk:streams:serialport Writing:$GPGSV,3,2,12,11,01,203,,13,59,283,23,14,35,131,40,15,28,286,09*72

Nov 28 11:46:10 2022-11-28T11:46:10.935Z signalk:streams:serialport Buffer overflow, not writing:$GPGSV,3,3,12,18,18,318,17,20,45,186,37,27,04,014,,30,66,075,30*78

Nov 28 11:46:10 2022-11-28T11:46:10.937Z signalk:streams:serialport Buffer overflow, not writing:$GPGLL,5115.60183,N,00040.67878,W,114611.00,A,A*77
tvr256 commented 1 year ago

I've been trying to find out whether flow control is (or should be enabled), and I found an interesting message from the OpenCPN lead developer here:

Of course, we could add the option to enable software or hardware flow control for special cases. But I have to say, in 10 years of interfacing OpenCPN to a variety of devices, we have never seen a device that could not process a few NMEA sentences at 1 Hz. rate. Never. If a device truly cannot keep up with a steady stream of NMEA data, then no amount of flow control will help them in the long term.

And, by the way, I have never seen an NMEA listener that included hardware flow-control pins. Very rare, if at all.

tvr256 commented 1 year ago

According to the Teensy documentation "the Teensy USB Serial object always communicates at native USB speed, either 12 or 480 Mbit/sec. The baud rate setting with Serial.begin(baud) is ignored with USB serial"

So the USB port is already communicating at maximum speed, and we could possibly remove USB_BAUDRATE from BoardConfig.h to avoid any confusion. On the other hand, it might be useful in future if we're porting to other platforms.

tvr256 commented 1 year ago

And here is the SignalK code which is producing the buffer overflow messages. If there are more than 5 sentences in the output buffer, any further input sentences are ignored:

https://github.com/SignalK/signalk-server/commit/0f2dcfadb37d6633f7959f4a096369a6d2202d7b

Rodemfr commented 1 year ago

Ok, it means that MTN cannot handle all sentences. I suspect the cause : MTN talks on SPI in CC1101's ISR. SPI is slow and probably blocks serial interrupt for too long if it is arriving at 480mbit/s ! I will look for a solution...

Rodemfr commented 1 year ago

Looking to Teensy's USB code, I see that the input buffer is of 512 bytes. At 480Mbit/s, I have less than 9us to collect the data. With the current MTN design, it will not be easy...

tvr256 commented 1 year ago

Or we could just ask the SignalK team to increase their output buffer size? 5 sentences isn't a very big buffer.

Rodemfr commented 1 year ago

I investigated this issue this morning, and here is what I found : I used a verbose NMEA simulator which sends bursts of NMEA sentences. I connected it to OpenCPN. OpenCPN is configured to add its own navigation related sentences and to forward all of this to MTN via USB. I see the same than you : a number of sentences are refused by COM port.

I made several of test on MTN side :

None of them changed the situation : always the same number of sentences are missed. So, I'm more and more thinking that the problems comes from Windows USB-Serial driver itself which probably has a too small input buffer, refusing data in case of a too long burst. I'm not yet sure of this but that's the direction I will follow. I will dig internet to see if COM driver buffers can be configured.

Rodemfr commented 1 year ago

I found an interesting comment here stating :

USB emulator drivers generally don't make much effort to simulate a serial port perfectly.
Things like baudrate, parity and handshaking just don't make sense on USB so are
completely faked out. This one clearly doesn't emulate a buffer size either.
It isn't clear why you worry about it but it is a non-issue. You must always pay attention
to the number of bytes (lpNumberOfBytesRead) that ReadFile() returns, it is only ever
equal to nNumberOfBytesToRead by accident. So just call ReadFile() repeatedly to fill
your own buffer. Btw, use the .NET SerialPort class to avoid the pinvoke.

I the last sentence is correct, It might explain why OpenCPN sees unsent data.

Rodemfr commented 1 year ago

Some progress on this issue. I tested MTN on USB with OpenCPN + NmeaSimulator under Linux : no sentences are lost with both CPU@24MHz and CPU@600MHz. So, everything points to Windows platform. My understanding is that it is a problem eof Windows Serial/USB driver, or from OpenCPN, or more likely of the combination of the two. I made many modifications on MTN side, including completely disabling everything but serial handling and it changes nothing to the issue.

I I have time I will try to modifiy OpenCPN to handle differently writes to COM ports, but now I close the issue. There is unfortunately nothing to do here on MTN side.