Port becomes unresponsive after receiving large amounts of data

[petertorelli]

Summary of Problem

• What are you trying to do? Receive data from a target device.

• What happens? I send a command to the device, which is a simple string "debuglines-N%" where N is an integer. The device returns N 32-byte lines. If I ask the device for small quantities by repeating "debuglines-10%" it works fine. If I ask for 1,000 lines, all 1,000 lines are received ONCE, but then the device no longer responds. (I cannot run a debugger because the USB is in use by the UART, and I cannot probe the UART pins because they are not exposed).

HOWEVER, if I use a different terminal app and manually type in the "debuglines-1000%", it never hangs, it continues to respond each subsequent call, even if I send 10,000 lines.

• What should have happened? I should be able to issue the command repeatedly and not lose communication. Or if something did go wrong, I would expect an exception or an "on:error" event. Some kind of feedback as to what state the serial port is in? I tried comparing both port objects before and after the crash and there appeared to be no difference (using console.log(port)).

Code to Reproduce the Issue

See more recent updates down in my comments. I have source for mbed and Arduino and a new node stress script...

Not sure how to provide the target code, since I doubt you would want to spend time flashing a STMicro device. But here is the JS code...

    let sp = new serialport('/dev/tty.usbmodem14143', { baudRate: 115200 });
    sp.on('open', () => {
        console.log('open');
    });
    sp.on('data', data => {
        console.log(data.toString());
    });
    sp.write('debuglines-1000%'); // dies after receiving all 1,000 lines
    sp.write('debuglines-1000%'); // target doesn't respond

Versions, Operating System and Hardware

• SerialPort@6.0.0 and @4.0.7 I cannot use anything above 7.0.0 due to all the macOS segfault issues

• Node.js v10.10.0, v10.11.0, v11.6.0

• Windows? Linux? Mac? macOS & Win10

• Hardware and chipset? (Prolific/FTDI/Other) ST_Link device. Not sure.

Thanks.

[petertorelli]

Note this does not happen on a PC testing with Node 6.10.0 and serialport 5.0.0: everything works fine.

[HipsterBrown]

Can you share the debug output from setting the DEBUG environment to *? https://serialport.io/docs/en/guide-debugging#linux-osx

Can you also try adding a callback to the write commands to see if an error is returned from that?

sp.write('debuglines-1000%', (error) => {
  if (error) console.error(error);
});

[petertorelli]

@HipsterBrown, thanks. I tried that. No error is generated by the write() function's callback. Also, the port.on('error') event is not triggered either.

Would it be helpful if I attached a small Arduino sketch?

[petertorelli]

@HipsterBrown Oh, and here's is the debug response after the subsequent "debuglines-10000%" command. (I added a little extra code on the remote device to let me know it's parser is ready by printing a string.)

9999: 
  serialport:main _read reading +0ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead waiting for readable because of code: EAGAIN +0ms
  serialport:poller Polling for "readable" +0ms
  serialport:poller received "readable" +1ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead Finished read 7 bytes +0ms
  serialport:main binding.read finished +0ms
ABCDEFG
  serialport:main _read reading +0ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead waiting for readable because of code: EAGAIN +0ms
  serialport:poller Polling for "readable" +0ms
  serialport:poller received "readable" +1ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead Finished read 16 bytes +0ms
  serialport:main binding.read finished +0ms
HIJKLMNOPQRSTUVW
  serialport:main _read reading +0ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead waiting for readable because of code: EAGAIN +0ms
  serialport:poller Polling for "readable" +0ms
  serialport:poller received "readable" +1ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead Finished read 11 bytes +0ms
  serialport:main binding.read finished +0ms
XYZABCDE
m
  serialport:main _read reading +0ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead waiting for readable because of code: EAGAIN +0ms
  serialport:poller Polling for "readable" +0ms
  serialport:poller received "readable" +1ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead Finished read 8 bytes +0ms
  serialport:main binding.read finished +0ms
-ready

  serialport:main _read reading +0ms
  serialport:bindings read +0ms
  serialport:unixRead Starting read +0ms
  serialport:unixRead waiting for readable because of code: EAGAIN +0ms
  serialport:poller Polling for "readable" +0ms

[HipsterBrown]

Thanks for sharing that. What does it look like when it is working on Windows?

I'm starting to think there is some issue between the polling required on max/linux systems vs the file events on windows. The EAGAIN signal:

serialport:unixRead waiting for readable because of code: EAGAIN +0ms

means there is no available data and the poller is just sitting waiting for more.

[petertorelli]

So it looks like Win10 is now also not behaving properly when I send back 10k lines, the second write command is ignored. Here's the debug=* output (using node v11.6.0 and serailport@7.1.3)..... am I using serialport wrong? I thought write was async... what happens on subsequent serialport.write() commands? Does serialport buffer them, or are they sent if the target UART is ready to receive? Do I need to do anything special when calling back-to-back write()?

Hmm... Now I wonder if it is the hardware? Odd, I'm using both latest mbed and STCubeMX versions which are essentially the same underlying UART CMSIS. Let me try an arduino...

Windows log. I'm expecting after the 10,000th line to see five lines, i.e. write('debuglines-10000%') and then write('debuglines-5%')...

Thanks!

9994: ABCDEFG
  serialport/stream _read reading +1ms
  serialport/binding-abstract read +4ms
  serialport/stream binding.read finished +2ms
HIJKLMNOPQRSTUVWXYZABCDE
9995: ABCDEFGHIJKLMN
  serialport/stream _read reading +12ms
  serialport/binding-abstract read +13ms
  serialport/stream binding.read finished +2ms
OPQRSTUVWXYZABCDE
9996: ABCDEFGHIJKLMNOPQRSTUVWXYZABCDE
9997: ABCDEFGHIJKLMNOPQRSTUVWXYZABCDE
9998: ABCDEFGHIJKLMNOPQRSTUVWXYZABCDE
9999: ABCDEFG
  serialport/stream _read reading +1ms
  serialport/binding-abstract read +4ms
  serialport/stream binding.read finished +2ms
HIJKLMNOPQRSTUVWXYZABCDE
m-ready

  serialport/stream _read reading +2ms
  serialport/binding-abstract read +3ms

[petertorelli]

Hi again @HipsterBrown Nick,

I started my stress experiments again and moved to win10 to use the latest serialport:

O/S: Windows10 Node: 10.11.0 Serialport: 7.1.3

I tested on 5 targets [board // stack // compiler (status)], only one passed:

Arduino UNO // arduino libs // avr-dude (pass) STMicro Nucleo L476RG // mbed-os + CMSIS uart // GCC_ARM (fail) STMicro Nucleo L476RG // STCubeMX + HAL uart // same (fail) STMicro Nucleo F429ZI // mbed-os + CMSIS uart // same (fail) Silicon Labs Pearl Gecko // mbed-os + CMSIS uart // same (fail)

Arduino sketch:

String command("");

void
setup() {
  Serial.begin(115200);
  Serial.flush();
  Serial.print("ready\n");
}

void
loop() {
  if (Serial.available()) {
    char c = Serial.read();
    if (c == '%') {
      int n = atoi(command.c_str());
      for (int i = 0; i < n; ++i) {
        Serial.print(i, DEC);
        Serial.print(":");
        // 32B
        Serial.print("abcdefghijklmnopqrstuvwxyz012345\n");
      }
      command = "";
    } else {
      command += c;
    }
  }
}

Mbed project:

#include "mbed.h"
#include <string>
#include <cstdio>

Serial uart(USBTX, USBRX, 115200);

std::string command("");

int
main() {
  printf("ready\n");
  while (1) {
    char c = uart.getc();
    if (c == '%') {
      int n = atoi(command.c_str());
      for (int i = 0; i < n; ++i) {
        printf("%d: %s\n", i, "abcdefghijklmnopqrstuvwxyz012345");
      }
      command.clear();  
    } else {
      command.push_back(c);
    }
  }
}

And the node script is modified to blast out more data: 10,000, then 10,000, then 5. This series caught another board failure (the pearl gecko passed 10,000+5 and failed 10,000+10,000+5).

const serialport = require('serialport')
const uart = new serialport('COM3', { baudRate: 115200 })
uart.on('open', () => { console.log('open') })
uart.on('data', data => { console.log(data.toString()); });
uart.on('error', error => { console.log('onerror', error) });
setTimeout(() => {
    uart.write('10000%', error => { console.log('Response from write #1:', error) })
    uart.write('10000%', error => { console.log('Response from write #2:', error) })
    uart.write('5%', error => { console.log('Response from write #3:', error) })
}, 3000) // <-- boot init for init-on-open devices (e.g. arduino)

Only the Arduino passed. The other four configurations hung without an error, throw, or onerror. The STM boards hung after the first run of 10,000 lines. The Pearl Gecko made it through the first 10,000 and then 10 lines of the next command.

The debug logs look the same. It sits there waiting for read data, and the write() callbacks have no error.

Where in the C++ library for serialport should I start dropping the printfs(). And how does one begin recompiling local npm modules? I've never debugged a native NPM module.

Thanks, Peter

[petertorelli]

I'm going to close this for now because I think it is related to the firmware stack and the UART FIFO depth. E.g., can the non-ISR parse loop be overflowing / dropping data while the lengthy print loop transmits? I'm not sure why the Arduino has no problem with this, but I don't think it is related to serialport. Thanks for the help @HipsterBrown