Node-serialport: How to reset a serialport connection

Created on 23 Jan 2018 · 13Comments · Source: serialport/node-serialport

__SerialPort Version__:6.0.4
__NodeJS Version__:4.8.2
__Operating System__ and __Hardware Platform__: Original Raspberry Pi 1 (armv6)
Have you checked the right __version__ of the __api docs?__: yes
Are you having trouble installing and you checked the __Installation Special Cases__ docs?
Are you using __Electron__ and have you checked the _Electron Docs_?: no

Summary of Problem

I am using serial port to connect to a Rainforest EMU2 energy monitoring device connecting to the USB port on the raspberry pi (original gen 1)
The connection works fine and I am able to connect to device and receive data.
However after 19 minutes the app stops receiving any data from the device.

If I kill my process and restart the process the device will connect again and the app will receive data but again stop after 19 minutes.
instead of trying to kill the process and restart I am trying to just close the serialport connection and start a new connection. However that does not seem to be working. How can I simulate the same effect of connecting to the device with a new serialport as if I am restarting my process.

I have tried deleting seriaport module from cache and reloading but nothing seems to be working.
Although the serialport shows open and the open callback method is called no data is being received from the device. While if i kill process and restart immediately the app is getting data.

Basicall serial.port open event is received but no data event is being received

(Actually after reading some other open issues - I am not sure if my device stops broadcasting or serialport stops receiving - My device also has a screen and data on that is being updated regularly, so thinking it maynot be the device)

Just tested the same issue running on Windows 10, node.js 8.9.4 same serialport version. here the timeout happens at 17 minutes instead of 19 minutes so does not seem to be device issue.
I windows i have to physically detach and reattach the USB cable for the port to even function on restart. without detach no data events received even on restart of process.

Further update - testing on RPi latest v3 - Node.js 9.4.0 same serialport. Port stops receiving around 15-19 minutes. However in this case the code below is able to reset connection (open a new connnection) and continue receiving data. So likely not an issue with the device but my code or serialport

Steps and Code to Reproduce the Issue

    console.log("Resetting port at ..." +  new Date());
    if (self.serialPort.isOpen) {
        //console.log("Port is open ...");
        self.serialPort.close();
    }   

    serialport = requireUncached("serialport"); 
    portparser  = new serialport.parsers.Readline;
    self.serialPort = new serialport(state.serialPath, {
        baudRate: 115200,
        dataBits: 8,
        stopBits: 1,
        parity: 'none',
    });
    self.serialPort.pipe(portparser);
    self.serialPort.on("open", function() { 
        openHandler(self);
    })

    //Using this uncache fuction to force reload of serialport

    function requireUncached(module){
    delete require.cache[require.resolve(module)]
    return require(module)
    }

HERE are some logs (actually getting too long so attaching file with the whole log from beginning till it fails and one a reset attempt from me)

raven.log

debug logs when port initially opened which works fine (some other triggers are happening in the process also)

debug logs in between 2 events being transmitted by device
demand: 1/22/2018, 7:02:19 PM : 1705.2  --> this is my app logging basically data event processed
  serialport:main _read reading +895ms
  serialport:bindings read +936ms
  serialport:unixRead Starting read +930ms
  serialport:unixRead waiting for readable because of code: EAGAIN +20ms
  serialport:poller Polling for "readable" +1s
  serialport:poller received "readable" +14s
  serialport:bindings read +14s
  serialport:unixRead Starting read +14s
  serialport:unixRead Finished read 178 bytes +12ms
  serialport:main binding.read finished +14s
  serialport:main _read reading +16ms
  serialport:bindings read +49ms
  serialport:unixRead Starting read +37ms
  serialport:unixRead Finished read 219 bytes +5ms
  serialport:main binding.read finished +30ms
demand: 1/22/2018, 7:02:34 PM : 1705.2


DEBUG logs after last event read a (looks like the port is still reading but no data event is being send)...
demand: 1/22/2018, 7:21:05 PM : 1713.6
  serialport:main _read reading +38ms
  serialport:bindings read +55ms
  serialport:unixRead Starting read +49ms
  serialport:unixRead waiting for readable because of code: EAGAIN +19ms
  serialport:poller Polling for "readable" +113ms
  serialport:poller received "readable" +15s
  serialport:bindings read +15s
  serialport:unixRead Starting read +15s
  serialport:unixRead Finished read 119 bytes +6ms
  serialport:main binding.read finished +15s
  serialport:main _read reading +8ms
  serialport:bindings read +26ms
  serialport:unixRead Starting read +19ms
  serialport:unixRead Finished read 278 bytes +9ms
  serialport:main binding.read finished +20ms
  serialport:main _read reading +4ms
  serialport:bindings read +25ms
  serialport:unixRead Starting read +15ms
  serialport:unixRead waiting for readable because of code: EAGAIN +5ms
  serialport:poller Polling for "readable" +68ms
  serialport:poller received "readable" +15s
  serialport:bindings read +15s
  serialport:unixRead Starting read +15s
  serialport:unixRead Finished read 122 bytes +6ms
  serialport:main binding.read finished +15s
  serialport:main _read reading +6ms
  serialport:bindings read +23ms
  serialport:unixRead Starting read +18ms
  serialport:unixRead Finished read 234 bytes +5ms
  serialport:main binding.read finished +17ms
  serialport:main _read reading +5ms
  serialport:bindings read +23ms
  serialport:unixRead Starting read +17ms
  serialport:unixRead Finished read 41 bytes +5ms
  serialport:main binding.read finished +17ms
  serialport:main _read reading +4ms
  serialport:bindings read +21ms
  serialport:unixRead Starting read +16ms
  serialport:unixRead waiting for readable because of code: EAGAIN +6ms
  serialport:poller Polling for "readable" +85ms
  serialport:poller received "readable" +3s
  serialport:bindings read +3s
  serialport:unixRead Starting read +3s
  serialport:unixRead Finished read 114 bytes +5ms
  serialport:main binding.read finished +3s
  serialport:main _read reading +9ms
  serialport:bindings read +27ms
  serialport:unixRead Starting read +22ms
  serialport:unixRead Finished read 83 bytes +5ms
  serialport:main binding.read finished +16ms
  serialport:main _read reading +5ms
  serialport:bindings read +21ms
  serialport:unixRead Starting read +18ms
  serialport:unixRead waiting for readable because of code: EAGAIN +6ms
  serialport:poller Polling for "readable" +68ms
  serialport:poller received "readable" +18s
  serialport:bindings read +18s
  serialport:unixRead Starting read +18s
  serialport:unixRead Finished read 54 bytes +4ms
(keeps on doing this forever my app tries to reset connection as per example code above)


Failed Poll: resetting port
Resetting port at ...Mon Jan 22 2018 19:22:03 GMT-0600 (CST)
  serialport:main #close +8s
  serialport:bindings close +8s
  serialport:poller Stopping poller +8s
  serialport:main binding.read error { [Error: Canceled] canceled: true } +34ms
  serialport:main _read queueing _read for after open +17ms
  serialport:main opening path: /dev/ttyACM0 +30s
  serialport:bindings open +30s
  serialport:main _read queueing _read for after open +22ms
  serialport:main binding.close finished +370ms
  serialport:poller Creating poller +30s
  serialport:main opened path: /dev/ttyACM0 +11ms
serial device opened at ...Mon Jan 22 2018 19:22:34 GMT-0600 (CST) (I included a timer to wait for 30 seconds after close  to open in case that was the problem)
  serialport:main _read reading +25ms
  serialport:bindings read +427ms
  serialport:unixRead Starting read +38s
  serialport:unixRead waiting for readable because of code: EAGAIN +5ms
  serialport:poller Polling for "readable" +47ms
  serialport:poller received "readable" +8s
  serialport:bindings read +8s
  serialport:unixRead Starting read +8s
  serialport:unixRead Finished read 119 bytes +6ms
  serialport:main binding.read finished +8s
  serialport:main _read reading +8ms
  serialport:bindings read +25ms
  serialport:unixRead Starting read +20ms
  serialport:unixRead Finished read 254 bytes +5ms
  serialport:main binding.read finished +17ms
  serialport:main _read reading +4ms
  serialport:bindings read +21ms
  serialport:unixRead Starting read +16ms
  serialport:unixRead Finished read 24 bytes +4ms
  serialport:main binding.read finished +16ms
  serialport:main _read reading +4ms
  serialport:bindings read +20ms
  serialport:unixRead Starting read +19ms
  serialport:unixRead waiting for readable because of code: EAGAIN +5ms
  serialport:poller Polling for "readable" +85ms
  serialport:poller received "readable" +12s
  serialport:bindings read +12s
  serialport:unixRead Starting read +12s
  serialport:unixRead Finished read 123 bytes +5ms
  serialport:main binding.read finished +12s
  serialport:main _read reading +4ms

(Basically looks like after reopening port again reading something but sending no data event)

stale-issue support

Source

sgupta999

Most helpful comment

Reconbot thanks for looking into this.

the device broadcasts an event every 15 seconds which triggers the call to the port 'data' callback function
In the ports 'data' callback function - as soon as you enter the function (i.e. the port received an event from the device) a flag is set signifying connection is working and data is being received.

I have another thread that polls that flag every 15 seconds if - if the flag is not set it increments a counter and after 2 failed tries it calls the reset port method and i print that info command

I know the device is working because besides broadcasting the event every 15 seconds it also udpate the data on its screen,

As you can see from the log file - between the last call to data from device (as represented by the 'demand' output and between the failed tries before i print the 'Failed Poll: resetting port'
looks the the data is still being read (and that matches with the fact that the device is updating data i its screen). Whats evident is that even though the debug is saying data is being read (and at 15 second intervals from what I can tell) but the 'data' callback function is not being called (the flag is not being set and none of the program logic in there is being executed).

IMPROTANT

so essentially what I can tell from the logs is that the debug command shows low level reads are happening but the callback 'data' function is not being called. (This seems to be the crux of the issue)

The fact is the even now the connection fails everytime (or 'data' callback functions stops being called) within 20 minutes.
From custom debut commands what i can tell in this state

no calls are being made to 'data' callback function (flag is not being set, logic not being executed)
isOpen() returns true (that's why I close it and wait 30 seconds before I open a new connection)
As soon as a new connection is open and callback is registered with serialPort.on('data', function(evtdata) {...}, the callback resumes.

About the cache - all i can say is if I do not clear it and reopen the port, the program just hangs indefinitely after the connection fail i.e. it assumes port is open and connected but it is not receiving the 'data' callback. Somehow the 'data' callback is resumed if I establish a new connection on the same port.

my workaround was working but after 3 days the port again became unresponsive. It wouldn't respond to even a restart of the program. I had to physically remove the USB connection and reconnect it again and it has been working since.

Very frustrating and not sure how to diagnose where the issue is.

sgupta999 on 5 Feb 2018

👍3

All 13 comments

This sounds a bit like a memory or file handle leak. It should be noted
that Close is an async operation, you might try waiting for the port to
close before opening it in another instance.

Are you creating a new port each time or reusing this one?

On Mon, Jan 22, 2018, 2:32 PM sgupta999 notifications@github.com wrote:

-

SerialPort Version:6.0.4
-

NodeJS Version:4.8.2
-

Operating System and Hardware Platform: Original Raspberry Pi 1
(armv6)
-

Have you checked the right version of the api docs?: yes
-

Are you having trouble installing and you checked the Installation
Special Cases docs? yes
-

Are you using Electron and have you checked the Electron Docs?: no

Summary of Problem

I am using serial port to connect to a Rainforest EMU2 energy monitoring
device connecting to the USB port on the raspberry pi.
The connection works fine and I am able to connect to device and receive
data.
However the device stops sending data after 15 minutes.
If I kill my process and restart the process the device will connect again
and start broadcasting.
instead of trying to kill the process and restart I am trying to just
close the serialport connection. start a new connection. However that does
not seem to be working. How can I simulate the same effect of connecting to
the device with a new serialport as if I am restarting my process.

I have tried deleting seriaport module from cache and reloading but
nothing seems to be working.
Although the serialport shows open and the open method is called no data
is being received from the device. While if i kill process and restart
immediately the device begins transmitting the data.
Steps and Code to Reproduce the Issue

console.log("Resetting port at ..." + new Date());
if (self.serialPort.isOpen) {
//console.log("Port is open ...");
self.serialPort.close();
}

serialport = requireUncached("serialport");
portparser = new serialport.parsers.Readline;
self.serialPort = new serialport(state.serialPath, {
baudRate: 115200,
dataBits: 8,
stopBits: 1,
parity: 'none',
});
self.serialPort.pipe(portparser);
self.serialPort.on("open", function() {
openHandler(self);
})

//Using this uncache fuction to force reload of serialport

function requireUncached(module){
delete require.cache[require.resolve(module)]
return require(module)
}

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/node-serialport/node-serialport/issues/1450, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AABlbl9-CskNSWQZeXMjWNH7YgXCSdOGks5tNSiygaJpZM4Ro35C
.

reconbot on 24 Jan 2018

Creating a new port each time.
I put all close commands in a separate function and calling openport with a 30 seconds timeout.
so 30 seconds between close and open (I have tried to change it to 60 no difference reallly). if i Ctrl C and kill process and restart (all within 10 seconds everything is working. Same behaviour on Rpi 1, Windows 10 and Rpi 3 - in RPi 3 I am actually able to reset.

Clearing serialport from cache so assuming no memory leaks but i could be wrong

function requireUncached(module){
    delete require.cache[require.resolve(module)]
    return require(module)
}

function resetPort(){   
    state.PORT_INITIALIZED = false;
    if (self.serialPort.isOpen) {
        winston.debug("Port is open ...closing");
        self.serialPort.close();
    }   
    setTimeout(openPort, 30000);
}

function openPort(){
    try {
        winston.info("Opening port");
            serialport = requireUncached("serialport");
        portparser  = new serialport.parsers.Readline;
        self.serialPort = new serialport(state.serialPath, {
            baudRate: 115200,
            dataBits: 8,
            stopBits: 1,
            parity: 'none',
        });
        self.serialPort.pipe(portparser);
        self.serialPort.on("open", function() { 
            openHandler(self);
        });
    } catch (ex){
        winston.error("ERROR opening port\n" + ex);
    }
}

sgupta999 on 24 Jan 2018

👍1

OK udpate - i found one issue
i had defined portparser as const in the top as originally i was not expecting to have to reset port and parsers. Fixing that now allows me to reset the port of Rpi 1 also.

However the port stops receiving data on all 3 installation between 15-19 minutes.. I need to figure out how to fix this - any help will be appreciated

sgupta999 on 24 Jan 2018

I've never had to mess with the require cache. If there's any state being kept it will be in the c++ module and there's no way to clear that.

It's not clear to me when resetPort is called.

You wrote Failed Poll: resetting port in the logs, how does that happen?

reconbot on 5 Feb 2018

Reconbot thanks for looking into this.

I have another thread that polls that flag every 15 seconds if - if the flag is not set it increments a counter and after 2 failed tries it calls the reset port method and i print that info command

I know the device is working because besides broadcasting the event every 15 seconds it also udpate the data on its screen,

IMPROTANT

The fact is the even now the connection fails everytime (or 'data' callback functions stops being called) within 20 minutes.
From custom debut commands what i can tell in this state

no calls are being made to 'data' callback function (flag is not being set, logic not being executed)
isOpen() returns true (that's why I close it and wait 30 seconds before I open a new connection)
As soon as a new connection is open and callback is registered with serialPort.on('data', function(evtdata) {...}, the callback resumes.

Very frustrating and not sure how to diagnose where the issue is.

sgupta999 on 5 Feb 2018

👍3

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in a week no further activity occurs. Feel free continue the discussion or ask for a never-stale label to keep it open. If this is a support issue, consider sharing it on stack overflow to get more eyes on your problem.

stale[bot] on 16 Sep 2018

I'm not convinced it's not a USB driver issue. The read code between windows and osx are not significantly different. We use nodejs's fs.read under the hood which is super well tested.

I wish I had a better answer here.

reconbot on 20 Sep 2018

Fact is the workaround seems to be working for now - I reset the connection everytime I detect that data is not being parsed. Sometime even the reset will not work for a few cycles but eventually it is able to reset and gets the data.

still very odd - definitely looks like a problem somewhere with the driver or the connection

sgupta999 on 20 Sep 2018

stale[bot] on 20 Nov 2018

😕1

i have the same problem with port after receiving more than ~32768 bytes no more 'on data' event. Closing and reopening port not resolving problem. I must restart application.

krzychu0905gmail on 22 Dec 2018

Is that a consistent number? What version, platform, os, etc

On Sat, Dec 22, 2018, 5:42 PM krzychu0905gmail notifications@github.com
wrote:

i have the same problem with port after receiving more than ~32768 bytes
no more 'on data' event. Closing and reopening port not resolving problem.
I must restart application.

—
You are receiving this because you commented.

Reply to this email directly, view it on GitHub
https://github.com/node-serialport/node-serialport/issues/1450#issuecomment-449602018,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AABlbg9CLg0qACtRxP__cV8D-Xo7TzqLks5u7rVhgaJpZM4Ro35C
.

reconbot on 22 Dec 2018

Os Raspian Strech, Node version 8.12.0, SerialPort version 6.5.0, device conventer USB/UART. Received frame have a dynamic length.
Last number of received data (in bytes) after which the serial did not receive any more data:
32779,
32776,
32775,
32775,
32775,
32781,
32777,
32772,
32777.
I can see the error occurs after exceeding the range of int16_t.