Serial gets data, but also times out

[mainstreetmark]

Hello - I'm following your ReadHoldingRegisters example (which uses readInputRegisters, fyi) and i cannot get it to work. Here is my output:

connecting to /dev/ttyUSB1 { baudRate: 9600, parity: 'none', stopBits: 1, dataBits: 8 } socket on open rtu-client-request-handler registrating new request +0ms catch { '0': { err: 'Timeout', message: 'Request timed out' } } rtu-response-handler receiving new data +0ms rtu-response-handler buffer <Buffer 01 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 ... > +0ms rtu-response address 1 buffer <Buffer 01 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 ... > +0ms rtu-response-handler crc 51210 +3ms rtu-response-handler reset buffer from 85 to 0 +0ms rtu-response-handler not enough data available to parse +1ms rtu-client-request-handler new response coming in +5s rtu-client-request-handler something is strange, received a respone without a request +0ms data { '0': <Buffer 01 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 ... > } close { '0': null }

As you can see, the buffer appears in the response, but the instant it does, it thinks it's timed out. Incidentally, the device i'm reading from can successfully be read via ModScan32 and another tool from https://www.modbusdriver.com/, so i know the device itself seems to work.

edit: the serial/usb device i'm using is this.

[stefanpoeter]

Can you post your code. Seems strange indeed.

[mainstreetmark]

Sure.

test2.js.txt

[stefanpoeter]

You catch the socket data twice in your js file. Remove the line

socket.on('data', function () {
  console.log("data", arguments)
})

And try again.

[mainstreetmark]

No difference. :(

It prints "socket on open", waits 5 seconds and prints the rest of that stuff.

I can see in the debug buffer the value 0xC220, which is real data. In fact, here's the same modbus request performed by modpoll (in 110ms, i should add):

$ modpoll /dev/ttyUSB0 -b 9600 -p none -r 200 -c 40 -t 4:hex modpoll 3.4 - FieldTalk(tm) Modbus(R) Master Simulator Copyright (c) 2002-2013 proconX Pty Ltd Visit http://www.modbusdriver.com for Modbus libraries and tools.

Protocol configuration: Modbus RTU Slave configuration...: address = 1, start reference = 200, count = 40 Communication.........: /dev/ttyUSB0, 9600, 8, 1, none, t/o 1.00 s, poll rate 1000 ms Data type.............: 16-bit register (hex), output (holding) register table

-- Polling slave... (Ctrl-C to stop)

[stefanpoeter]

Can you log a timestamp of the request and one for the catch and post the output. I want to see how much time has passed. The data seems to come in ok, just too late.

[mainstreetmark]

1546614143854 0 'connecting to' '/dev/ttyUSB0' { baudRate: 9600, parity: 'none', stopBits: 1, dataBits: 8 } 1546614143888 34 'socket on open' 1546614148908 5054 'catch' { '0': { err: 'Timeout', message: 'Request timed out' } } 1546614148916 5062 'close' { '0': null }

First number is Date.now(), second number is elapsed time since the "connecting to" event.

If I change the timeout value on rtu-client-request-handler.js:19, the log reflects the change. So, yes, it is definitely timing out. So, something is failing to inform the handler that data has arrived.

[mainstreetmark]

Here is a full DEBUG=*.

serialport/bindings loading LinuxBinding +0ms 1546615502219 0 'connecting to' '/dev/ttyUSB0' { baudRate: 9600, parity: 'none', stopBits: 1, dataBits: 8, timeout: 10000 } serialport/stream opening path: /dev/ttyUSB0 +0ms serialport/binding-abstract open +0ms serialport/stream _read queueing _read for after open +4ms serialport/bindings/poller Creating poller +0ms serialport/stream opened path: /dev/ttyUSB0 +5ms 1546615502234 15 'socket on open' modbus-client issuing new read holding registers request +0ms rtu-client-request-handler registrating new request +0ms user-request creating new user request with timeout 5000 +0ms client-request-handler flushing +0ms client-request-handler flushing new request <Buffer 01 03 00 c8 00 28 c4 2a> +3ms serialport/stream _write 8 bytes of data +10ms serialport/binding-abstract write 8 bytes +18ms serialport/stream _read reading +1ms serialport/binding-abstract read +1ms serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +0ms serialport/bindings/unixRead Starting read +0ms serialport/bindings/unixWrite write returned null 8 +2ms serialport/bindings/unixWrite wrote 8 bytes +1ms serialport/bindings/unixWrite Finished writing 8 bytes +0ms serialport/stream binding.write write finished +4ms client-request-handler request fully flushed, ( error: undefined ) undefined +8ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +4ms serialport/bindings/poller Polling for "readable" +19ms serialport/bindings/poller received "readable" +14ms serialport/binding-abstract read +23ms

^^ The 5000ms timeout is visible after this line

client-request-handler flushing +5s client-request-handler no request to be executed +0ms serialport/bindings/unixRead Starting read +5s 1546615507253 5034 'catch' { '0': { err: 'Timeout', message: 'Request timed out' } } serialport/stream #close +5s serialport/binding-abstract close +5s serialport/bindings/poller Stopping poller +5s serialport/bindings/poller Destroying poller +1ms serialport/bindings/unixRead Finished read 85 bytes +8ms serialport/stream binding.read finished +5ms modbus-client received data +5s rtu-response-handler receiving new data +0ms rtu-response-handler buffer <Buffer 01 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 ... > +0ms rtu-response address 1 buffer <Buffer 01 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 ... > +0ms response-factory fc 3 payload <Buffer 03 50 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 20 00 00 c2 20 00 00 ... > +0ms ReadHoldingRegistersResponseBody ReadHoldingRegistersResponseBody values [ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 49696, 0, 49696, 0, 0, 0, 0, 0, 0, 0, 49696, 0, 49696, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ] +0ms rtu-response-handler crc 51210 +4ms rtu-response-handler reset buffer from 85 to 0 +0ms rtu-response-handler not enough data available to parse +1ms rtu-client-request-handler new response coming in +5s rtu-client-request-handler something is strange, received a respone without a request +1ms serialport/stream _read queueing _read for after open +8ms serialport/stream binding.close finished +1ms 1546615507270 5051 'close' { '0': null }

[stefanpoeter]

Seems ok by me. The client does not receive data for five seconds and therefor returns an error. What operating system are you using? Maybe have a look at the serialport module, seems like the error is located there.

[mainstreetmark]

Great. Hopefully the #227 guy will report back on what sort of setup he's using. Otherwise I'm stuck.

[mainstreetmark]

Oh, Ubuntu 18

[sivakatru]

Same issue at my side with Ubuntu 16. I guess, its something inline with #195