node-red shutdown after connection loss and reconnect attempt

maccap commented 6 years ago

Problem

(x) bug report => please search github for a similar issue or PR before submitting
( ) unexpected behavior => please visit the Wiki before

Information

Current behavior node-red is working as opc-client and doing a simple read tasks of several variables in a 2 second interval. Everything works fine until I disconnect the Ethernet-cable to the plc system (opc server). I get a timeout after 60.000ms regardless which time I set in the connector node. When I reconnect the cable it takes some time and then suddenly my whole node-red collaps. This does not occur everytime, but 2-4 times out of 10. If I start node-red without connection to the opc server and then connect the cable to the server it always crashes...

This is my error-log: 2 Nov 11:02:13 - [error] [OPCUA-IIoT-Connector:MEBA] Error: Transaction has timed out ( timeout = 60000 ms)

at Timeout._onTimeout (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1020:27)

at ontimeout (timers.js:498:11)

at tryOnTimeout (timers.js:323:5)

at Timer.listOnTimeout (timers.js:290:5)

Timeout .... waiting for response for CloseSessionRequest { /RequestHeader/

authenticationToken / NodeId /: ns=0;i=56

timeStamp / UtcTime /: 2018-11-02T11:01:13.981Z

requestHandle / IntegerId /: 76 0x4c

returnDiagnostics / UInt32 /: 0 0x0

auditEntryId / UAString /:

timeoutHint / UInt32 /: 0 0x0

additionalHeader / ExtensionObject /: null

};

ERROR !!! , please check here !!!! callback may be called twice !! Error: Callback was already called.

at /data/node_modules/async/dist/async.js:966:32

at /data/node_modules/async/dist/async.js:1137:13

at /data/node_modules/node-opcua-client/src/client_base.js:868:13

at /data/node_modules/node-opcua-client/src/opcua_client.js:728:9

at /data/node_modules/node-opcua-client/src/opcua_client.js:693:13

at Object.<anonymous> (/data/node_modules/node-opcua-client/src/client_session.js:1168:20)

at Object.modified_callback [as callback] (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1005:28)

at ClientSecureChannelLayer.cancelPendingTransactions (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1298:25)

at ClientSecureChannelLayer.close (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1319:10)

at OPCUAClientBase.disconnect (/data/node_modules/node-opcua-client/src/client_base.js:964:21)

ERROR !!! , please check here !!!! callback may be called twice !! Error: Callback was already called.

at /data/node_modules/async/dist/async.js:966:32

at /data/node_modules/async/dist/async.js:1137:13

at /data/node_modules/node-opcua-client/src/client_base.js:868:13

at /data/node_modules/node-opcua-client/src/opcua_client.js:728:9

at /data/node_modules/node-opcua-client/src/opcua_client.js:693:13

at /data/node_modules/node-opcua-client/src/client_session.js:1168:20

at Object.modified_callback [as callback] (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1009:13)

at ClientSecureChannelLayer.cancelPendingTransactions (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1298:25)

at ClientSecureChannelLayer.close (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1319:10)

at OPCUAClientBase.disconnect (/data/node_modules/node-opcua-client/src/client_base.js:964:21)

2 Nov 11:02:13 - [red] Uncaught Exception:

2 Nov 11:02:13 - Error: Callback was already called.

at /data/node_modules/async/dist/async.js:966:32

at /data/node_modules/async/dist/async.js:1137:13

at /data/node_modules/node-opcua-client/src/client_base.js:868:13

at /data/node_modules/node-opcua-client/src/opcua_client.js:728:9

at /data/node_modules/node-opcua-client/src/opcua_client.js:693:13

at /data/node_modules/node-opcua-client/src/client_session.js:1168:20

at modified_callback (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1009:13)

at Timeout._onTimeout (/data/node_modules/node-opcua-secure-channel/src/client/client_secure_channel_layer.js:1020:9)

at ontimeout (timers.js:498:11)

at tryOnTimeout (timers.js:323:5)

npm ERR! code ELIFECYCLE

npm ERR! errno 1

npm ERR! node-red-docker@1.0.0 start: node $NODE_OPTIONS node_modules/node-red/red.js -v $FLOWS "--userDir" "/data"

npm ERR! Exit status 1

npm ERR!

npm ERR! Failed at the node-red-docker@1.0.0 start script.

npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:

npm ERR! /usr/src/node-red/.npm/_logs/2018-11-02T11_02_13_999Z-debug.log

Expected behavior

Minimal reproduction of the problem with instructions [{"id":"c6ae5e61.f1978","type":"OPCUA-IIoT-Inject","z":"97217c23.abbd9","injectType":"inject","payload":"","payloadType":"date","topic":"","repeat":"2","crontab":"","once":false,"startDelay":"10","name":"Werte abholen","addressSpaceItems":[{"name":"iOPC_UA_Sollstueckzahl","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_Sollstueckzahl","datatypeName":""},{"name":"iOPC_UA_KuehlwZustInProz","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_KuehlwZustInProz","datatypeName":""},{"name":"iOPC_UA_KuehlwMengeInProz","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_KuehlwMengeInProz","datatypeName":""},{"name":"sOPC_UA_AktSB","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_AktSB","datatypeName":""},{"name":"sOPC_UA_BandfZustInProz","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_BandfZustInProz","datatypeName":""},{"name":"sOPC_UA_VerschmutzZustAllgInProzent","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_VerschmutzZustAllgInProzent","datatypeName":""},{"name":"sOPC_UA_VerschlSpaehnebuersteInProzent","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_VerschlSpaehnebuersteInProzent","datatypeName":""},{"name":"sOPC_UA_KuehlwFuellstandInProz","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_KuehlwFuellstandInProz","datatypeName":""},{"name":"sOPC_UA_KuehlwQualitaetInProzent","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_KuehlwQualitaetInProzent","datatypeName":""},{"name":"sOPC_UA_SpruehQualitaetInProzent","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_SpruehQualitaetInProzent","datatypeName":""},{"name":"xOPC_UA_Running","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_Running","datatypeName":""},{"name":"xOPC_UA_Waiting","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_Waiting","datatypeName":""},{"name":"xOPC_UA_Error","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_Error","datatypeName":""},{"name":"xOPC_UA_AutoRunning","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_AutoRunning","datatypeName":""},{"name":"xOPC_UA_DatenaustauschLokal","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_DatenaustauschLokal","datatypeName":""},{"name":"xOPC_UA_AuftragPlanungVonSystemUebergeordet","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_AuftragPlanungVonSystemUebergeordet","datatypeName":""},{"name":"iOPC_UA_Auftragssytem","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_Auftragssytem","datatypeName":""},{"name":"sOPC_UA_Maschinentyp","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_Maschinentyp","datatypeName":""},{"name":"sOPC_UA_Maschinennummer","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.sOPC_UA_Maschinennummer","datatypeName":""},{"name":"xOPC_UA_SBandVerschleisInProzAktAuftrag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.xOPC_UA_SBandVerschleisInProzAktAuftrag","datatypeName":""},{"name":"iOPC_UA_VerbrauchWasserAktAuftrag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_VerbrauchWasserAktAuftrag","datatypeName":""},{"name":"iOPC_UA_KostenProSchnitt","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_KostenProSchnitt","datatypeName":""},{"name":"iOPC_UA_EnergieProStueck","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieProStueck","datatypeName":""},{"name":"iOPC_UA_EnergieAktAuftrag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieAktAuftrag","datatypeName":""},{"name":"iOPC_UA_EnergieProTag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieProTag","datatypeName":""},{"name":"iOPC_UA_EnergieProWoche","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieProWoche","datatypeName":""},{"name":"iOPC_UA_EnergieProMonat","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieProMonat","datatypeName":""},{"name":"iOPC_UA_EnergieProJahr","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_EnergieProJahr","datatypeName":""},{"name":"iOPC_UA_AuftraegeGesaegtProTag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_AuftraegeGesaegtProTag","datatypeName":""},{"name":"iOPC_UA_AuftraegeGesaegtProWoche","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_AuftraegeGesaegtProWoche","datatypeName":""},{"name":"iOPC_UA_AuftraegeGesaegtProMonat","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_AuftraegeGesaegtProMonat","datatypeName":""},{"name":"iOPC_UA_AuftraegeGesaegtProJahr","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_AuftraegeGesaegtProJahr","datatypeName":""},{"name":"iOPC_UA_StueckzahlGesaegtProTag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StueckzahlGesaegtProTag","datatypeName":""},{"name":"iOPC_UA_StueckzahlGesaegtProWoche","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StueckzahlGesaegtProWoche","datatypeName":""},{"name":"iOPC_UAStueckzahlGesaegtProMonat","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UAStueckzahlGesaegtProMonat","datatypeName":""},{"name":"iOPC_UA_StueckzahlGesaegtProJahr","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StueckzahlGesaegtProJahr","datatypeName":""},{"name":"iOPC_UA_ZerspanleistungAktAuftrag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_ZerspanleistungAktAuftrag","datatypeName":""},{"name":"iOPC_UA_ZerspanleistungProTag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_ZerspanleistungProTag","datatypeName":""},{"name":"iOPC_UA_ZerspanleistunProWoche","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_ZerspanleistunProWoche","datatypeName":""},{"name":"iOPC_UA_ZerspanleistungProMonat","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_ZerspanleistungProMonat","datatypeName":""},{"name":"iOPC_UA_ZerspanleistungProJahr","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_ZerspanleistungProJahr","datatypeName":""},{"name":"iOPC_UA_StoermeldungenAktAuftrag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StoermeldungenAktAuftrag","datatypeName":""},{"name":"iOPC_UA_StoermeldungenProTag","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StoermeldungenProTag","datatypeName":""},{"name":"iOPC_UA_StoermeldungenProWoche","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StoermeldungenProWoche","datatypeName":""},{"name":"iOPC_UA_StoermeldungenProMonat","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StoermeldungenProMonat","datatypeName":""},{"name":"iOPC_UA_StoermeldungenProJahr","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.iOPC_UA_StoermeldungenProJahr","datatypeName":""},{"name":"dwOPC_UA_StoermeldungStatistik","nodeId":"ns=4;s=|var|p500.Application.OPC_Variablen.dwOPC_UA_StoermeldungStatistik","datatypeName":""}],"x":355,"y":269,"wires":[["2631705e.27ec88"]]},{"id":"2631705e.27ec88","type":"OPCUA-IIoT-Read","z":"97217c23.abbd9","attributeId":"13","maxAge":1,"depth":1,"connector":"31b769b0.d1272e","name":"","justValue":true,"showStatusActivities":true,"showErrors":true,"parseStrings":false,"historyDays":"","x":539,"y":272,"wires":[["bf40d4d7.b795d"]]},{"id":"bf40d4d7.b795d","type":"debug","z":"97217c23.abbd9","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","x":703.5,"y":272,"wires":[]},{"id":"31b769b0.d1272e","type":"OPCUA-IIoT-Connector","z":"","discoveryUrl":"","endpoint":"opc.tcp://192.168.5.99:4840","keepSessionAlive":false,"loginEnabled":false,"securityPolicy":"None","securityMode":"NONE","name":"MEBA","showErrors":true,"publicCertificateFile":"","privateKeyFile":"","defaultSecureTokenLifetime":"","endpointMustExist":false,"autoSelectRightEndpoint":false,"strategyMaxRetry":"","strategyInitialDelay":"","strategyMaxDelay":"","strategyRandomisationFactor":"","requestedSessionTimeout":"5000","connectionStartDelay":"","reconnectDelay":"","maxBadSessionRequests":"5"}]

Your Environment

Please tell us about your environment: I am running node-red v0.19.5 with node-red-contrib-iiot-opcua V3.0.0 and nodejs V8.12.0

(x ) I am using just the Node-RED package and got node-opcua installed with it
( ) I have installed node-opcua global from source (using git clone)
( ) I have installed node-opcua as a global package (using npm i -g)
Device :
- ( ) macOS: v
- (x) Linux: v
- ( ) Windows: v
- ( ) Raspbian: v
- ( ) Other:
  - Name:
  - Version:
- Description of the connecting OPC UA system:
  - Name: CODESYS_OPC_UA_Server
  - Version: 3.9.0.7
  - Vendor : Lenze
  - Link : https://

node-red-contrib-iiot-opcua version: ``
Node: (min. 8.x) node --version = 8.12.10

biancode commented 6 years ago

@erossignon do you have some idea about that? - it is 0.4.6 of node-opcua

biancode commented 6 years ago

It never happens with a software OPC UA server. I'll test it with PLC200 if I find some time.

maccap commented 6 years ago

In order to save time I can provide you openvpn access to my PLC device

biancode commented 6 years ago

In order to save time I can provide you openvpn access to my PLC device

Great - sure send me an e-mail., please

biancode commented 6 years ago

test protocol: VPN disconnected - creating a whole new client "Error: Transaction has timed out ( timeout = 60000 ms)" - raises never any timeout - wait was 4 min console log: "Invalid socket => Communication has been lost, cannot renew token"

biancode commented 6 years ago

timeout is fixed in node-opcua channel with min 30 sec.

request.requestHeader.timeoutHint || defaultTransactionTimeout (60 sec.)
timeout = Math.max(minTransactionTimeout, timeout);

biancode commented 6 years ago

"Timeout .... waiting for response for PublishRequest " on closed connection same test with VPN brings now "Error: Connection Break" and all is working well

biancode commented 6 years ago

Please, test v3.4.0!

maccap commented 6 years ago

Hello Klaus, Great work. Now nodered running stable after reconnecting the connection cable. I have tracked down two different behaviors regarding the fault state. Max Delay is set to 30s in connector mode

case a) after 60s when cable is disconnected the following message is shown: "Error: Transaction has timed out ( timeout = 60000 ms)" "Error: Client Not SESSIONACTIVE On Read" When I reconnect the cable it takes 60s again to get my connection reestablished and read correct data. In this case the max delay time is not working properly.

case b) If I start nodered with disconnected cable I get this output: "Error: Client Not SESSIONACTIVE On Read" and 10s later this: "Error: Backoff aborted." When I connect the cable it takes about 2- 4 s and the connection is working properly again

The main issue is fixed with your new version. Thank you very much.

biancode commented 6 years ago

case a) please @erossignon could you answer this? - I mean it is fixed in node-opcua by the client channel transaction timeout (_performMessageTransaction / defaultTransactionTimeout) for now - the session is to control and would use your settings

BiancoRoyal / node-red-contrib-iiot-opcua