search

jisotalo / node-red-contrib-ads-client

Beckhoff TwinCAT ADS client library for Node-RED (unofficial). Connects to Beckhoff TwinCAT automation systems using ADS protocol.
https://flows.nodered.org/node/node-red-contrib-ads-client
MIT License
15 stars 4 forks source link

Uncaught error #13

Closed Hopperpop closed 2 years ago

Hopperpop commented 3 years ago

Getting uncaught errors (node-red-contrib-ads-client v1.2.0), which stops node-red. I'm not sure if it's a problem with the node or the ads-client lib. It always happens after "IO out--->". The TcSystem isn't running. Somehow it tries to subscribe to a variable, while it just made a disconnect call. Could be a race condition, but I still need to investigate further.

  ads-client setDebugging(): Debug level set to 3 +2s
  ads-client connect(): Starting to connect localhost:48898 +1ms
  ads-client connect(): Socket connection established to localhost:48898 +8ms
  ads-client:details _registerAdsPort(): Registering an ADS port from ADS router localhost:48898 +2s
  ads-client:details IO out ------> 8 bytes +1ms
  ads-client:details IO in  <------ 14 bytes +0ms
  ads-client:details _parseAmsTcpHeader(): Starting to parse AMS/TCP header +1ms
  ads-client:details _parseAmsTcpHeader(): AMS/TCP header parsed: { command: 4096, commandStr: 'AMS_TCP_PORT_CONNECT', dataLength: 8, data: <Buffer c0 a8 00 c2 01 01 61 a4> } +0ms
  ads-client:details _parseAmsHeader(): Starting to parse AMS header +1ms
  ads-client:details _parseAmsHeader(): No AMS header found +1ms
  ads-client:details _parseAdsData(): Starting to parse ADS data +2ms
  ads-client:details _parseAdsData(): No ADS data found +3ms
  ads-client:details _onAmsTcpPacketReceived(): A parsed AMS packet received with command 4096 +1ms
  ads-client:details _registerAdsPort(): ADS port registered, assigned AMS address is 192.168.0.194.1.1:42081 +6ms
  ads-client connect(): ADS port registered from router. We are 192.168.0.194.1.1:42081 +21ms
  ads-client:details readSystemManagerState(): Reading device system manager state +9ms
  ads-client:details _sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsNetId: '127.0.0.1.1.1', targetAdsPort: 10000, sourceAmsNetId: '192.168.0.194.1.1', sourceAdsPort: 42081, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 0 }, ads: { rawData: <Buffer > } } +7ms
  ads-client:details _createAmsHeader(): AMS header created (32 bytes) +12ms
  ads-client:details _createAmsTcpHeader(): AMS/TCP header created (6 bytes) +6ms
  ads-client:details _createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +6ms
  ads-client:details IO in  <------ 38 bytes +1ms
  ads-client:details _parseAmsTcpHeader(): Starting to parse AMS/TCP header +2ms
  ads-client:details _parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', dataLength: 32 } +2ms
  ads-client:details _parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details _parseAmsHeader(): AMS header parsed: { targetAmsNetId: '192.168.0.194.1.1', targetAdsPort: 42081, sourceAmsNetId: '127.0.0.1.1.1', sourceAdsPort: 10000, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 0, errorCode: 18, invokeId: 0, error: true, errorStr: 'Port disabled' } +4ms
  ads-client:details _onAmsTcpPacketReceived(): A parsed AMS packet received with command 0 +1ms
  ads-client:details _onAdsCommandReceived(): A parsed ADS command received with command 4 +1ms
  ads-client:details _sendAdsCommand(): Response received for command ReadState with invokeId 0 +2ms
  ads-client readSystemManagerState(): Device system manager state read failed +50ms
  ads-client disconnect(): Starting to close connection (force: false) +3ms
  ads-client unsubscribeAll(): Unsubscribing from all notifications +3ms
  ads-client unsubscribeAll(): Unsubscribed from 0 notifications +0ms
  ads-client _unsubscribeAllInternals(): Unsubscribing from all notifications +3ms
  ads-client _unsubscribeAllInternals(): Unsubscribed from 0 notifications +2ms
  ads-client:details _unregisterAdsPort(): Unregister ads port 42081 from localhost:48898 +12ms
  ads-client:details IO out ------> 8 bytes +1ms
  ads-client subscribe(): Subscribing to MAIN.lrDt +3ms
  ads-client:details _subscribe(): Subscribing to 'MAIN.lrDt' with settings { transmissionMode: 4, cycleTime: 200, maximumDelay: 0 } +4ms
  ads-client getSymbolInfo(): Symbol info requested for MAIN.lrDt +3ms
  ads-client:details _readSymbolInfo(): Reading symbol info for MAIN.lrDt +1ms
  ads-client:details _sendAdsCommand(): Sending an ads command ReadWrite (26 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsNetId: '127.0.0.1.1.1', targetAdsPort: '851', sourceAmsNetId: '192.168.0.194.1.1', sourceAdsPort: 42081, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 26, errorCode: 0, invokeId: 1 }, ads: { rawData: <Buffer 09 f0 00 00 00 00 00 00 ff ff ff ff 0a 00 00 00 4d 41 49 4e 2e 6c 72 44 74 00> } } +11ms
  ads-client:details _createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details _createAmsTcpHeader(): AMS/TCP header created (6 bytes) +1ms
  ads-client:details _createAmsTcpRequest(): AMS/TCP request created (64 bytes) +1ms
  ads-client:details IO out ------> 64 bytes +1ms
1 Jul 17:21:56 - [red] Uncaught Exception:
1 Jul 17:21:56 - Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)
jisotalo commented 3 years ago

Thanks for reporting, again!

It seems that the PLC isn't available (Device system manager state read failed) and the ads-client disconnects, as there is nothing to connect to (except router).

However, in ads-client, the connected is set to true after getting ADS port from router. So it says "connected" too early. See line 392: https://github.com/jisotalo/ads-client/blob/master/src/ads-client.js#L392 The connected flag should be set to true near line 458 so it's not too early. This needs to be fixed.

From your log, we can see that the subscribe node is trying to subscribe at the same time the ads-client is disconnecting. However, there should be no uncaught exception, as all calls to the _socketWrite() are inside try...catch. Perhaps the reason is that the socket.on('error', this._internals.socketErrorHandler) line, which adds error event listener to socket, is after connected = true line..? Maybe try..catch isn't working with socket.write and the on('error') is the only way.

Edit: Yeah it might be it. There are those few lines during the error listener isn't active (lines 392..420). https://stackoverflow.com/a/17637900/8140625

jisotalo commented 3 years ago

Actually it's not too easy. Everything after that connected = true line depends on a valid connection.

Everything works if the connect() is waited to finish, but if, like in Node-RED, tries to do stuff already during connecting, things get dirty.

Needs some rethinking.

Hopperpop commented 3 years ago

If we make the following change:

this.isConnected = () => this.adsClient === null ? false : this.adsClient.connection.connected && !this.isConnecting()

And use the proposal from my pull-request #11 to be able to handle concurrent connect calls. Wouldn't that solve it? You basically as you said wait for the connect() function to end.

jisotalo commented 3 years ago

That makes sense. Good idea.

I'm also working on update to the ads-client, so that the connected is set after we are really connected. But this isConnected() change won't harm anything even after that.

Hopperpop commented 3 years ago

I installed version v1.3.0 and after multiple times starting and stopping the system manager, I got the ECONNRESET again.

ads-client: WARNING: Connection was lost. Trying to reconnect...
ads-client: WARNING: Local AMS router state has changed to START. Reconnecting...
ads-client: WARNING: Connection was lost. Trying to reconnect...
ads-client: WARNING: Local AMS router state has changed to START. Reconnecting...
ads-client: WARNING: Connection was lost. Trying to reconnect...
8 Jul 16:41:37 - [red] Uncaught Exception:
8 Jul 16:41:37 - Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)

Similar to #12 I see multiple warnings regarding Reconnect/Lost/... I wouldn't say it multiplies exactly each time I reconnect, but I'm getting more and more warnings. And it's definitely more than the amount of ads nodes in the flow.

For reference: I have a TwinCat program with TC_Stop functionblock to stop the systemmanager, and following flow: afbeelding

jisotalo commented 3 years ago

I'll try to find the reason.

What is the output if you set the debugging level to something higher? (1 or 2)

Hopperpop commented 3 years ago

Here I have a full log of a crash on debug level 2: Node-red.log

jisotalo commented 3 years ago

I just updated ads-client to 1.11.1.

I managed to get the system work better, couldn't get any issues anymore with my Raspberry Pi.

However, after releasing it and testing one more time, I once managed to get another problem. The client connected again and again, even though it connected successfully in between. But now I can't seem to cause that again, will keep trying. That happened when I first started Node-RED so that PLC was in config mode. Then I started to change between run and config and BAM.

So if you like, please test if updating ads-client to 1.11.1 helps for your problems.

ads-client [1.11.1] - 10.07.2021

Changed

jisotalo commented 2 years ago

Closing this as no more new reports & ads-client version 1.12.0 should also work on these issues.