Internal state-machine corrupted in specific circumstances

[emcell]

Which node-red-contrib-modbus version are you using?

5.25.0, 5.31.0, 5.40.0

What happened?

Modbus-Flex-Getter stops sending requests to modbus server after a specific set of messages

Server

Other/External server

How can this be reproduced?

I've figured out that this happens when you add 3 modbus-requests to the queue at the same time. The Problem happens after a request that times out.

1. Send a modbus-request that will timeout
2. 2 other modbus requests to the same unit-id (but different than the one in 1.). The other 2 requests could also timeout. that doesn't make any difference
3. You'll get the following message in the log:

   node:util:225: 24 Jun 06:50:15 - [warn] [modbus-client:modbus-bridge] sequential dequeue command not possible for Unit 1
   node:util:225: 24 Jun 06:50:15 - [warn] [modbus-client:modbus-bridge] no sending is allowed for Unit 1
   node:util:225: 24 Jun 06:50:15 - [warn] [modbus-client:modbus-bridge] valid Unit 1
   node:util:225: 24 Jun 06:50:15 - [warn] [modbus-client:modbus-bridge] modbus-bridge serial sending allowed for Unit 1

After that every modbus-request will just be added to the queue. But no request will be sent out.

my testing flow:

[{"id":"aa34a56821263bcc","type":"modbus-flex-getter","z":"62681542d268c879","name":"","showStatusActivities":true,"showErrors":true,"showWarnings":true,"logIOActivities":false,"server":"79e791b851e85bfc","useIOFile":false,"ioFile":"","useIOForPayload":false,"emptyMsgOnFail":false,"keepMsgProperties":false,"delayOnStart":false,"startDelayTime":"","x":600,"y":320,"wires":[["41a0ec4784e118fa"],[]]},{"id":"b7a2f4d4bbb3cd36","type":"inject","z":"62681542d268c879","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":180,"y":320,"wires":[["10fc83cf6df5cbf8"]]},{"id":"10fc83cf6df5cbf8","type":"function","z":"62681542d268c879","name":"function 81","func":"\nnode.send({payload: { fc: 4, unitid: 14, address: 0, quantity: 1 }})\nnode.send({payload: { fc: 3, unitid: 137, address: 20498, quantity: 2 }})\n//node.send({payload: { fc: 3, unitid: 1, address: 20498, quantity: 2 }})\n node.send({payload: { fc: 3, unitid: 137, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n// node.send({payload: { fc: 3, unitid: 1, address: 24576, quantity: 2 }})\n","outputs":1,"timeout":0,"noerr":0,"initialize":"","finalize":"","libs":[],"x":390,"y":320,"wires":[["aa34a56821263bcc"]]},{"id":"41a0ec4784e118fa","type":"debug","z":"62681542d268c879","name":"debug 288","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","statusVal":"","statusType":"auto","x":830,"y":320,"wires":[]},{"id":"79e791b851e85bfc","type":"modbus-client","name":"modbus-bridge","clienttype":"tcp","bufferCommands":true,"stateLogEnabled":true,"queueLogEnabled":true,"failureLogEnabled":true,"tcpHost":"127.0.0.1","tcpPort":"502","tcpType":"DEFAULT","serialPort":"/dev/ttyACM0","serialType":"RTU-BUFFERD","serialBaudrate":"9600","serialDatabits":"8","serialStopbits":"1","serialParity":"none","serialConnectionDelay":"10","serialAsciiResponseStartDelimiter":"0x3A","unit_id":"27","commandDelay":"10","clientTimeout":"1000","reconnectOnTimeout":false,"reconnectTimeout":"500","parallelUnitIdsAllowed":false,"showErrors":false,"showWarnings":true,"showLogs":true}]

I've tested against a real modbus-tcp server. But it's also possible to reproduce this with a simple socat command

socat - TCP-LISTEN:502,fork,reuseaddr

clear text modbus-request i'm using

node.send({payload: { fc: 4, unitid: 14, address: 0, quantity: 1 }}) // has to timeout 
node.send({payload: { fc: 3, unitid: 137, address: 20498, quantity: 2 }}) // needs the same unit id as request 3, but different to 1
node.send({payload: { fc: 3, unitid: 137, address: 24576, quantity: 2 }}) // needs the same unit id as request 2, but different to 1

I've tried to debug all this an found out that request 2 is going out and the state machine immedately (it does not wait until the response from request 2 is incoming) tries to send request 3. I tried to fix this ans make a pull request But I couldn't figure out how. Everything I've tried just made things worse ...

What did you expect to happen?

• I'd expect that the client wait's until the request 2 is finished before sending the next request.
• I'd also expect that it's not possible to get into a state where the node isn't sending out requests anymore and is just queueing.

Other Information

• Node-RED version: 3.1.0
• NodeJS version: v18.16.0

[emcell]

I've made a pairing session with a colleague and I think we found a solution. I've opened a pull request.

[MaryamJalil]

@emcell, Could you please write a test case for this as well?

[emcell]

Hi @MaryamJalil,

I tried to write a test case, but failed. I'm really not used to write code in non typescript projects and I've never used sinon before.

I couldn't figure out how I can install a sinon spy on modbusClientNode.coreModbusQueue.sendQueueDataToModbus since coreModbusQueue is not part of the modbusClientNode. I've seen that you created stubs for coreModbusQueue in other tests. But I'm pretty sure that they're not called in those tests either. In fact, I've added an assert on the stub of this test should handle error without a message in modbusSerialErrorHandling and log JSON stringified error and it hasn't been called.

I have no other ideas how to test my bugfix. Can you point me into the right direction?