node-red-contrib-opcua
node-red-contrib-opcua copied to clipboard
mikakaraila
OPC UA client crashes on Siemens S7-1500 after seconds to minutes
We are using OPC UA for reading and writing multiple values to a Siemens S7-1500 PLC. Unfortunatly the connection crashes after some seconds to minutes. This also leads to a crash and restart of the NodeRed docker container.
Here the dependencies from the package.json file.
"dependencies": {
"node-red": "3.1",
"node-red-dashboard":"3.6.0",
"node-red-contrib-opcua": "0.2.314",
"node-red-node-ui-table":"0.4.3",
"node-red-node-email":"2.0.1",
"node-red-node-base64":"0.3.0",
"pdfjs-dist": "3.9.179"
}
Here the NodeRed logs:
14 Sep 10:10:33 - [info] Starting flows
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 WRITE
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500
14 Sep 10:10:34 - [info] Started flows
Certificate manager initialized for node: PLC S7-1500
Client connecting, node: PLC S7-1500
08:10:34.367Z :client_base_impl :585 Creating default certificate ... please wait
Certificate manager initialized for node: PLC S7-1500
Client connecting, node: PLC S7-1500
Certificate manager initialized for node: PLC S7-1500 WRITE
Client connecting, node: PLC S7-1500 WRITE
Certificate manager initialized for node: PLC S7-1500
Client connecting, node: PLC S7-1500
Client connected, node: PLC S7-1500
Create session for node: PLC S7-1500
08:10:37.596Z :client_secure_channel_layer :236 requestData not found for requestId = 2 try with 3
14 Sep 10:10:37 - [red] Uncaught Exception:
14 Sep 10:10:37 - [error] TypeError: Cannot read properties of undefined (reading 'callback')
at MessageBuilder.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:243:42)
at MessageBuilder.emit (node:events:513:28)
at MessageBuilder._report_error (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:128:14)
at MessageBuilder._feed_messageChunk (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:193:22)
at PacketAssembler.<anonymous> (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:64:66)
at PacketAssembler.emit (node:events:513:28)
at PacketAssembler.feed (/usr/src/node-red/node_modules/node-opcua-packet-assembler/dist/packet_assembler.js:75:18)
at MessageBuilder.feed (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:94:35)
at ClientSecureChannelLayer._on_receive_message_chunk (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:964:29)
at ClientTCP_transport.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:809:18)
I tried to deactivate the 4 active session nodes one by one to identify the flow which causes this problems but it seems to be a more a problem in general... Any ideas?
Thanks in advance!
Try first without writing values to PLC.
Then activate following debug settings: set NODEOPCUADEBUG="CLIENT{TRACE-REQUEST-RESPONSE}" set NODEOPCUADEBUG="SERVER{TRACE-REQUEST-RESPONSE}" set ARRAY_LENGTH=2000 set NODEOPCUA_DEBUG_MAXLINE_PER_MESSAGE=200
You should see low level messages on console. It can be message size or write only value is possible (no timestamps nor status code).
Into the environment variables, so as node-red starts it will use those.
These two lines overwrites themself?
set NODEOPCUADEBUG="CLIENT{TRACE-REQUEST-RESPONSE}"
set NODEOPCUADEBUG="SERVER{TRACE-REQUEST-RESPONSE}"
I added the env variables to the container in which NodeRed is running but do not get more output in the log.
Hostname:/usr/src/node-red# printenv | grep NODEOPC
NODEOPCUADEBUG=SERVER{TRACE-REQUEST-RESPONSE}
NODEOPCUA_DEBUG_MAXLINE_PER_MESSAGE=200
Hostname:/usr/src/node-red# printenv | grep ARRA
ARRAY_LENGTH=2000
Use CLIENT environment not SERVER, output should be on console. DId you add environment variables into (inside) the Docker instance?
To remove the SERVER env variable does the trick...
Here the log of the last crash:
15 Sep 10:17:36 - [info] Starting flows
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 READ CHOOSEN PROGRAM
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 WRITE
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 SUBSCRIPTION
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 WRITE MSG
15 Sep 10:17:36 - [info] Started flows
08:17:36:750 <<<<<< ------ C 395 3028653198 10 CloseSessionResponse s= 24 Good (0x00000000)
08:17:36:751 >>>>>> ------ C 395 3028653198 11 CloseSecureChannelRequest s= 29
08:17:36:753 <<<<<< ------ C 387 3028653190 31 ServiceFault s= 24 BadNoSubscription (0x80790000)
08:17:36:755 <<<<<< ------ C 387 3028653190 32 ServiceFault s= 24 BadNoSubscription (0x80790000)
08:17:36:756 <<<<<< ------ C 387 3028653190 33 ServiceFault s= 24 BadNoSubscription (0x80790000)
08:17:36:756 <<<<<< ------ C 387 3028653190 34 ServiceFault s= 24 BadNoSubscription (0x80790000)
08:17:36:760 <<<<<< ------ C 387 3028653190 35 DeleteSubscriptionsResponse s= 36 Good (0x00000000)
08:17:36:760 >>>>>> ------ C 387 3028653190 36 CloseSessionRequest s= 35
08:17:36:850 <<<<<< ------ C 387 3028653190 36 CloseSessionResponse s= 24 Good (0x00000000)
08:17:36:851 >>>>>> ------ C 387 3028653190 37 CloseSecureChannelRequest s= 29
15 Sep 10:17:36 - [info] [mqtt-broker:MQTT Broker] Connected to broker: mqtts://xxxxxxxxxxx:8883
Certificate manager initialized for node: PLC S7-1500 READ CHOOSEN PROGRAM
Client connecting, node: PLC S7-1500 READ CHOOSEN PROGRAM
Certificate manager initialized for node: PLC S7-1500 WRITE
Client connecting, node: PLC S7-1500 WRITE
Certificate manager initialized for node: PLC S7-1500 SUBSCRIPTION
Client connecting, node: PLC S7-1500 SUBSCRIPTION
Certificate manager initialized for node: PLC S7-1500 WRITE MSG
Client connecting, node: PLC S7-1500 WRITE MSG
08:17:37:135 >>>>>> ------ C 396 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
08:17:37:141 <<<<<< ------ C 396 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
08:17:37:142 >>>>>> ------ C 396 3028653199 2 GetEndpointsRequest s= 70
08:17:37:149 <<<<<< ------ C 396 3028653199 2 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:37:150 >>>>>> ------ C 396 3028653199 3 GetEndpointsRequest s= 70
08:17:37:159 <<<<<< ------ C 396 3028653199 3 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:37:160 >>>>>> ------ C 396 3028653199 4 CloseSecureChannelRequest s= 29
08:17:37:202 >>>>>> ------ C 397 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
08:17:38:726 <<<<<< ------ C 397 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
08:17:38:727 >>>>>> ------ C 397 3028653200 2 GetEndpointsRequest s= 70
08:17:38:740 >>>>>> ------ C 398 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
08:17:38:751 <<<<<< ------ C 397 3028653200 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 READ CHOOSEN PROGRAM
Create session for node: PLC S7-1500 READ CHOOSEN PROGRAM
08:17:38:752 >>>>>> ------ C 397 3028653200 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
08:17:38:765 >>>>>> ------ C 399 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
08:17:38:766 <<<<<< ------ C 398 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
08:17:38:766 >>>>>> ------ C 398 3028653201 2 GetEndpointsRequest s= 70
08:17:39:783 <<<<<< ------ C 397 3028653200 3 CreateSessionResponse ns=1;i=2117277394 to:30000ms s= 4796 Good (0x00000000)
08:17:39:786 >>>>>> ------ C 397 3028653200 4 ActivateSessionRequest UserName s= 723
08:17:39:790 >>>>>> ------ C 400 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
08:17:39:791 <<<<<< ------ C 399 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
08:17:39:792 >>>>>> ------ C 399 3028653202 2 GetEndpointsRequest s= 70
08:17:39:800 <<<<<< ------ C 398 3028653201 2 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:39:801 >>>>>> ------ C 398 3028653201 3 GetEndpointsRequest s= 70
08:17:40:414 <<<<<< ------ C 397 3028653200 4 ActivateSessionResponse s= 68 Good (0x00000000)
Session created for node: PLC S7-1500 READ CHOOSEN PROGRAM
08:17:40:419 <<<<<< ------ C 400 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
08:17:40:419 >>>>>> ------ C 400 3028653203 2 GetEndpointsRequest s= 70
08:17:40:427 <<<<<< ------ C 399 3028653202 2 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:40:428 >>>>>> ------ C 399 3028653202 3 GetEndpointsRequest s= 70
08:17:40:436 <<<<<< ------ C 398 3028653201 3 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:40:437 >>>>>> ------ C 398 3028653201 4 CloseSecureChannelRequest s= 29
08:17:40:442 >>>>>> ------ C 401 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
08:17:40:453 <<<<<< ------ C 400 3028653203 2 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:40:454 >>>>>> ------ C 400 3028653203 3 GetEndpointsRequest s= 70
08:17:40:462 <<<<<< ------ C 399 3028653202 3 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:40:462 >>>>>> ------ C 399 3028653202 4 CloseSecureChannelRequest s= 29
08:17:40:483 <<<<<< ------ C 400 3028653203 3 GetEndpointsResponse s= 3392 Good (0x00000000)
08:17:40:484 >>>>>> ------ C 400 3028653203 4 CloseSecureChannelRequest s= 29
08:17:42:018 <<<<<< ------ C 401 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
08:17:42:049 >>>>>> ------ C 402 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
08:17:42:071 >>>>>> ------ C 403 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
08:17:42:086 >>>>>> ------ C 404 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
08:17:43:590 <<<<<< ------ C 402 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
08:17:43:590 >>>>>> ------ C 402 3028653205 2 GetEndpointsRequest s= 70
08:17:45:107 <<<<<< ------ C 403 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
08:17:45:108 >>>>>> ------ C 403 3028653206 2 GetEndpointsRequest s= 70
08:17:45:118 <<<<<< ------ C 402 3028653205 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 WRITE
Create session for node: PLC S7-1500 WRITE
08:17:45:119 >>>>>> ------ C 402 3028653205 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
08:17:46:619 <<<<<< ------ C 404 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
08:17:46:619 >>>>>> ------ C 404 3028653207 2 GetEndpointsRequest s= 70
08:17:46.621Z :client_secure_channel_layer :236 requestData not found for requestId = 1 try with 2
08:17:46.621Z :client_secure_channel_layer :241 message was 2: <null>
15 Sep 10:17:46 - [red] Uncaught Exception:
15 Sep 10:17:46 - [error] TypeError: Cannot read properties of undefined (reading 'callback')
at MessageBuilder.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:243:42)
at MessageBuilder.emit (node:events:513:28)
at MessageBuilder._report_error (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:128:14)
at MessageBuilder._feed_messageChunk (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:193:22)
at PacketAssembler.<anonymous> (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:64:66)
at PacketAssembler.emit (node:events:513:28)
at PacketAssembler.feed (/usr/src/node-red/node_modules/node-opcua-packet-assembler/dist/packet_assembler.js:75:18)
at MessageBuilder.feed (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:94:35)
at ClientSecureChannelLayer._on_receive_message_chunk (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:964:29)
at ClientTCP_transport.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:809:18)
What you try to write? Problem seems to be in write as I expected...
Or are there still sessions left on server? How many sessions it will support / any other clients connected to server?
Here another crash-log right after deploying an update of the nodeRed flows.
15 Sep 13:56:06 - [info] Starting flows
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 READ CHOOSEN PROGRAM
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 WRITE
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 SUBSCRIPTION
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 WRITE MSG
Node securityPolicy: Basic256Sha256
Certificate manager initialization for node: PLC S7-1500 READ MACHINE STATUS
15 Sep 13:56:06 - [info] Started flows
Certificate manager initialized for node: PLC S7-1500 WRITE
Client connecting, node: PLC S7-1500 WRITE
Certificate manager initialized for node: PLC S7-1500 READ CHOOSEN PROGRAM
Client connecting, node: PLC S7-1500 READ CHOOSEN PROGRAM
Certificate manager initialized for node: PLC S7-1500 SUBSCRIPTION
Client connecting, node: PLC S7-1500 SUBSCRIPTION
Certificate manager initialized for node: PLC S7-1500 WRITE MSG
Client connecting, node: PLC S7-1500 WRITE MSG
Certificate manager initialized for node: PLC S7-1500 READ MACHINE STATUS
Client connecting, node: PLC S7-1500 READ MACHINE STATUS
11:56:06:590 <<<<<< ------ C 286 3028654148 3 CreateSessionResponse ns=1;i=578387338 to:30000ms s= 4796 Good (0x00000000)
11:56:06.591Z :reconnection :403 session restoration has failed! err = Cannot complete subscription republish due to session termination ns=1;i=578387338 => Let's retry
11:56:06.591Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully
11:56:06:598 <<<<<< ------ C 284 3028654146 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.598Z :client_session_impl :147 client is now attempting to recreate a session
11:56:06:602 >>>>>> ------ C 284 3028654146 11 ActivateSessionRequest UserName s= 723
11:56:06:606 <<<<<< ------ C 283 3028654145 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.606Z :client_session_impl :147 client is now attempting to recreate a session
11:56:06:610 >>>>>> ------ C 283 3028654145 11 ActivateSessionRequest UserName s= 723
11:56:06:612 <<<<<< ------ C 285 3028654147 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.612Z :client_session_impl :147 client is now attempting to recreate a session
11:56:06:615 >>>>>> ------ C 285 3028654147 11 ActivateSessionRequest UserName s= 723
11:56:06:625 <<<<<< ------ C 284 3028654146 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.625Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=3272695547 => Let's retry
11:56:06.625Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully
11:56:06:625 >>>>>> ------ C 284 3028654146 12 CloseSessionRequest s= 35
11:56:06:634 <<<<<< ------ C 283 3028654145 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.634Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=2894026016 => Let's retry
11:56:06.634Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully
11:56:06:634 >>>>>> ------ C 283 3028654145 12 CloseSessionRequest s= 35
11:56:06:641 >>>>>> ------ C 287 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
11:56:06:646 <<<<<< ------ C 285 3028654147 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06.647Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=2357000091 => Let's retry
11:56:06.647Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully
11:56:06:647 >>>>>> ------ C 285 3028654147 12 CloseSessionRequest s= 35
11:56:06:657 <<<<<< ------ C 284 3028654146 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06:657 >>>>>> ------ C 284 3028654146 13 CloseSecureChannelRequest s= 29
11:56:06:667 <<<<<< ------ C 283 3028654145 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06:668 >>>>>> ------ C 283 3028654145 13 CloseSecureChannelRequest s= 29
11:56:06:671 >>>>>> ------ C 288 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
11:56:06:677 <<<<<< ------ C 287 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
11:56:06:678 >>>>>> ------ C 287 3028654149 2 GetEndpointsRequest s= 70
11:56:06:685 <<<<<< ------ C 285 3028654147 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
11:56:06:686 >>>>>> ------ C 285 3028654147 13 CloseSecureChannelRequest s= 29
11:56:06:699 >>>>>> ------ C 289 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
11:56:06:709 <<<<<< ------ C 288 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
11:56:06:710 >>>>>> ------ C 288 3028654150 2 GetEndpointsRequest s= 70
11:56:06:718 <<<<<< ------ C 287 3028654149 2 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:719 >>>>>> ------ C 287 3028654149 3 GetEndpointsRequest s= 70
11:56:06:734 >>>>>> ------ C 290 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
11:56:06:741 <<<<<< ------ C 289 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
11:56:06:742 >>>>>> ------ C 289 3028654151 2 GetEndpointsRequest s= 70
11:56:06:751 <<<<<< ------ C 288 3028654150 2 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:752 >>>>>> ------ C 288 3028654150 3 GetEndpointsRequest s= 70
11:56:06:758 <<<<<< ------ C 287 3028654149 3 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:759 >>>>>> ------ C 287 3028654149 4 CloseSecureChannelRequest s= 29
11:56:06:766 >>>>>> ------ C 291 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49
11:56:06:772 <<<<<< ------ C 290 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
11:56:06:772 >>>>>> ------ C 290 3028654152 2 GetEndpointsRequest s= 70
11:56:06:779 <<<<<< ------ C 289 3028654151 2 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:779 >>>>>> ------ C 289 3028654151 3 GetEndpointsRequest s= 70
11:56:06:787 <<<<<< ------ C 288 3028654150 3 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:787 >>>>>> ------ C 288 3028654150 4 CloseSecureChannelRequest s= 29
11:56:06:806 <<<<<< ------ C 291 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000)
11:56:06:807 >>>>>> ------ C 291 3028654153 2 GetEndpointsRequest s= 70
11:56:06:808 <<<<<< ------ C 290 3028654152 2 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:809 >>>>>> ------ C 290 3028654152 3 GetEndpointsRequest s= 70
11:56:06:818 <<<<<< ------ C 289 3028654151 3 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:819 >>>>>> ------ C 289 3028654151 4 CloseSecureChannelRequest s= 29
11:56:06:839 <<<<<< ------ C 291 3028654153 2 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:840 >>>>>> ------ C 291 3028654153 3 GetEndpointsRequest s= 70
11:56:06:842 <<<<<< ------ C 290 3028654152 3 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:842 >>>>>> ------ C 290 3028654152 4 CloseSecureChannelRequest s= 29
11:56:06:870 <<<<<< ------ C 291 3028654153 3 GetEndpointsResponse s= 3392 Good (0x00000000)
11:56:06:871 >>>>>> ------ C 291 3028654153 4 CloseSecureChannelRequest s= 29
11:56:06:883 >>>>>> ------ C 292 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:06:891 >>>>>> ------ C 293 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:06:901 >>>>>> ------ C 294 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:08:426 <<<<<< ------ C 292 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:08:427 >>>>>> ------ C 292 3028654154 2 GetEndpointsRequest s= 70
11:56:08:430 >>>>>> ------ C 295 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:09:933 <<<<<< ------ C 293 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:09:935 >>>>>> ------ C 293 3028654155 2 GetEndpointsRequest s= 70
11:56:09:941 >>>>>> ------ C 296 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:11:440 <<<<<< ------ C 294 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:11:441 >>>>>> ------ C 294 3028654156 2 GetEndpointsRequest s= 70
11:56:11:448 <<<<<< ------ C 292 3028654154 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 WRITE
Create session for node: PLC S7-1500 WRITE
11:56:11:450 >>>>>> ------ C 292 3028654154 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
11:56:11:466 <<<<<< ------ C 293 3028654155 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 WRITE MSG
Create session for node: PLC S7-1500 WRITE MSG
11:56:11:467 >>>>>> ------ C 293 3028654155 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
11:56:11:485 <<<<<< ------ C 294 3028654156 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 READ CHOOSEN PROGRAM
Create session for node: PLC S7-1500 READ CHOOSEN PROGRAM
11:56:11:486 >>>>>> ------ C 294 3028654156 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
11:56:12:988 <<<<<< ------ C 295 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:12:988 >>>>>> ------ C 295 3028654157 2 GetEndpointsRequest s= 70
11:56:14:000 <<<<<< ------ C 292 3028654154 3 CreateSessionResponse ns=1;i=2997230216 to:30000ms s= 4796 Good (0x00000000)
11:56:14:003 >>>>>> ------ C 292 3028654154 4 ActivateSessionRequest UserName s= 723
11:56:15:020 <<<<<< ------ C 293 3028654155 3 CreateSessionResponse ns=1;i=3814582517 to:30000ms s= 4796 Good (0x00000000)
11:56:15:024 >>>>>> ------ C 293 3028654155 4 ActivateSessionRequest UserName s= 723
11:56:16:522 <<<<<< ------ C 296 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:16:523 >>>>>> ------ C 296 3028654158 2 GetEndpointsRequest s= 70
Error on create session for node: PLC S7-1500 READ CHOOSEN PROGRAM
15 Sep 13:56:16 - [error] [OpcUa-Client:PLC S7-1500 READ CHOOSEN PROGRAM] Client node error on: PLC S7-1500 READ CHOOSEN PROGRAM error: ["PLC S7-1500 READ CHOOSEN PROGRAM OPC UA connection error: ClientTCP_transport294: socket has been disconnected by third party"]
11:56:16:541 <<<<<< ------ C 295 3028654157 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 READ MACHINE STATUS
Create session for node: PLC S7-1500 READ MACHINE STATUS
11:56:16:542 >>>>>> ------ C 295 3028654157 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
11:56:17:144 <<<<<< ------ C 292 3028654154 4 ActivateSessionResponse s= 68 Good (0x00000000)
Session created for node: PLC S7-1500 WRITE
11:56:17:755 <<<<<< ------ C 293 3028654155 4 ActivateSessionResponse s= 68 Good (0x00000000)
Session created for node: PLC S7-1500 WRITE MSG
11:56:17:762 <<<<<< ------ C 296 3028654158 2 GetEndpointsResponse s= 3392 Good (0x00000000)
Client connected, node: PLC S7-1500 SUBSCRIPTION
Create session for node: PLC S7-1500 SUBSCRIPTION
11:56:17:763 >>>>>> ------ C 296 3028654158 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392
11:56:18:785 <<<<<< ------ C 295 3028654157 3 CreateSessionResponse ns=1;i=2315717238 to:30000ms s= 4796 Good (0x00000000)
11:56:18:789 >>>>>> ------ C 295 3028654157 4 ActivateSessionRequest UserName s= 723
11:56:19:809 <<<<<< ------ C 296 3028654158 3 CreateSessionResponse ns=1;i=1648881698 to:30000ms s= 4796 Good (0x00000000)
11:56:19:817 >>>>>> ------ C 296 3028654158 4 ActivateSessionRequest UserName s= 723
11:56:19:819 >>>>>> ------ C 297 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
11:56:20:426 <<<<<< ------ C 295 3028654157 4 ActivateSessionResponse s= 68 Good (0x00000000)
Session created for node: PLC S7-1500 READ MACHINE STATUS
11:56:21:029 <<<<<< ------ C 296 3028654158 4 ActivateSessionResponse s= 68 Good (0x00000000)
Session created for node: PLC S7-1500 SUBSCRIPTION
11:56:21:164 >>>>>> ------ C 296 3028654158 5 CreateSubscriptionRequest s= 56
11:56:22:544 <<<<<< ------ C 297 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
11:56:22.545Z :client_secure_channel_layer :236 requestData not found for requestId = 3 try with 4
11:56:22.545Z :client_secure_channel_layer :241 message was 2: <null>
15 Sep 13:56:22 - [red] Uncaught Exception:
15 Sep 13:56:22 - [error] TypeError: Cannot read properties of undefined (reading 'callback')
at MessageBuilder.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:243:42)
at MessageBuilder.emit (node:events:513:28)
at MessageBuilder._report_error (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:128:14)
at MessageBuilder._feed_messageChunk (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:193:22)
at PacketAssembler.<anonymous> (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:64:66)
at PacketAssembler.emit (node:events:513:28)
at PacketAssembler.feed (/usr/src/node-red/node_modules/node-opcua-packet-assembler/dist/packet_assembler.js:75:18)
at MessageBuilder.feed (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:94:35)
at ClientSecureChannelLayer._on_receive_message_chunk (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:964:29)
at ClientTCP_transport.<anonymous> (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:809:18)
Only this nodered instance is active on the server.
It is possible that "old" sessions of the same container are left on the server? How I can close a session probably? This problem occurs in most cases right after deploying in nodeRed or sometimes during running of the program.
Server is responsible to cleanup old sessions
On Fri, Sep 15, 2023, 15:03 nico @.***> wrote:
Here another crash-log right after deploying an update of the nodeRed flows.
15 Sep 13:56:06 - [info] Starting flows Node securityPolicy: Basic256Sha256 Certificate manager initialization for node: PLC S7-1500 READ CHOOSEN PROGRAM Node securityPolicy: Basic256Sha256 Certificate manager initialization for node: PLC S7-1500 WRITE Node securityPolicy: Basic256Sha256 Certificate manager initialization for node: PLC S7-1500 SUBSCRIPTION Node securityPolicy: Basic256Sha256 Certificate manager initialization for node: PLC S7-1500 WRITE MSG Node securityPolicy: Basic256Sha256 Certificate manager initialization for node: PLC S7-1500 READ MACHINE STATUS 15 Sep 13:56:06 - [info] Started flows Certificate manager initialized for node: PLC S7-1500 WRITE Client connecting, node: PLC S7-1500 WRITE Certificate manager initialized for node: PLC S7-1500 READ CHOOSEN PROGRAM Client connecting, node: PLC S7-1500 READ CHOOSEN PROGRAM Certificate manager initialized for node: PLC S7-1500 SUBSCRIPTION Client connecting, node: PLC S7-1500 SUBSCRIPTION Certificate manager initialized for node: PLC S7-1500 WRITE MSG Client connecting, node: PLC S7-1500 WRITE MSG Certificate manager initialized for node: PLC S7-1500 READ MACHINE STATUS Client connecting, node: PLC S7-1500 READ MACHINE STATUS 11:56:06:590 <<<<<< ------ C 286 3028654148 3 CreateSessionResponse ns=1;i=578387338 to:30000ms s= 4796 Good (0x00000000) 11:56:06.591Z :reconnection :403 session restoration has failed! err = Cannot complete subscription republish due to session termination ns=1;i=578387338 => Let's retry 11:56:06.591Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully 11:56:06:598 <<<<<< ------ C 284 3028654146 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.598Z :client_session_impl :147 client is now attempting to recreate a session 11:56:06:602 >>>>>> ------ C 284 3028654146 11 ActivateSessionRequest UserName s= 723 11:56:06:606 <<<<<< ------ C 283 3028654145 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.606Z :client_session_impl :147 client is now attempting to recreate a session 11:56:06:610 >>>>>> ------ C 283 3028654145 11 ActivateSessionRequest UserName s= 723 11:56:06:612 <<<<<< ------ C 285 3028654147 10 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.612Z :client_session_impl :147 client is now attempting to recreate a session 11:56:06:615 >>>>>> ------ C 285 3028654147 11 ActivateSessionRequest UserName s= 723 11:56:06:625 <<<<<< ------ C 284 3028654146 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.625Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=3272695547 => Let's retry 11:56:06.625Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully 11:56:06:625 >>>>>> ------ C 284 3028654146 12 CloseSessionRequest s= 35 11:56:06:634 <<<<<< ------ C 283 3028654145 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.634Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=2894026016 => Let's retry 11:56:06.634Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully 11:56:06:634 >>>>>> ------ C 283 3028654145 12 CloseSessionRequest s= 35 11:56:06:641 >>>>>> ------ C 287 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49 11:56:06:646 <<<<<< ------ C 285 3028654147 11 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06.647Z :reconnection :403 session restoration has failed! err = reconnection cancelled due to session termination ns=1;i=2357000091 => Let's retry 11:56:06.647Z :reconnection :414 session restoration should be interrupted because session has been closed forcefully 11:56:06:647 >>>>>> ------ C 285 3028654147 12 CloseSessionRequest s= 35 11:56:06:657 <<<<<< ------ C 284 3028654146 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06:657 >>>>>> ------ C 284 3028654146 13 CloseSecureChannelRequest s= 29 11:56:06:667 <<<<<< ------ C 283 3028654145 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06:668 >>>>>> ------ C 283 3028654145 13 CloseSecureChannelRequest s= 29 11:56:06:671 >>>>>> ------ C 288 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49 11:56:06:677 <<<<<< ------ C 287 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000) 11:56:06:678 >>>>>> ------ C 287 3028654149 2 GetEndpointsRequest s= 70 11:56:06:685 <<<<<< ------ C 285 3028654147 12 ServiceFault s= 24 BadSessionIdInvalid (0x80250000) 11:56:06:686 >>>>>> ------ C 285 3028654147 13 CloseSecureChannelRequest s= 29 11:56:06:699 >>>>>> ------ C 289 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49 11:56:06:709 <<<<<< ------ C 288 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000) 11:56:06:710 >>>>>> ------ C 288 3028654150 2 GetEndpointsRequest s= 70 11:56:06:718 <<<<<< ------ C 287 3028654149 2 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:719 >>>>>> ------ C 287 3028654149 3 GetEndpointsRequest s= 70 11:56:06:734 >>>>>> ------ C 290 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49 11:56:06:741 <<<<<< ------ C 289 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000) 11:56:06:742 >>>>>> ------ C 289 3028654151 2 GetEndpointsRequest s= 70 11:56:06:751 <<<<<< ------ C 288 3028654150 2 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:752 >>>>>> ------ C 288 3028654150 3 GetEndpointsRequest s= 70 11:56:06:758 <<<<<< ------ C 287 3028654149 3 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:759 >>>>>> ------ C 287 3028654149 4 CloseSecureChannelRequest s= 29 11:56:06:766 >>>>>> ------ C 291 0 1 OpenSecureChannelRequest Issue None lt:600000ms s= 49 11:56:06:772 <<<<<< ------ C 290 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000) 11:56:06:772 >>>>>> ------ C 290 3028654152 2 GetEndpointsRequest s= 70 11:56:06:779 <<<<<< ------ C 289 3028654151 2 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:779 >>>>>> ------ C 289 3028654151 3 GetEndpointsRequest s= 70 11:56:06:787 <<<<<< ------ C 288 3028654150 3 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:787 >>>>>> ------ C 288 3028654150 4 CloseSecureChannelRequest s= 29 11:56:06:806 <<<<<< ------ C 291 0 1 OpenSecureChannelResponse s= 53 Good (0x00000000) 11:56:06:807 >>>>>> ------ C 291 3028654153 2 GetEndpointsRequest s= 70 11:56:06:808 <<<<<< ------ C 290 3028654152 2 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:809 >>>>>> ------ C 290 3028654152 3 GetEndpointsRequest s= 70 11:56:06:818 <<<<<< ------ C 289 3028654151 3 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:819 >>>>>> ------ C 289 3028654151 4 CloseSecureChannelRequest s= 29 11:56:06:839 <<<<<< ------ C 291 3028654153 2 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:840 >>>>>> ------ C 291 3028654153 3 GetEndpointsRequest s= 70 11:56:06:842 <<<<<< ------ C 290 3028654152 3 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:842 >>>>>> ------ C 290 3028654152 4 CloseSecureChannelRequest s= 29 11:56:06:870 <<<<<< ------ C 291 3028654153 3 GetEndpointsResponse s= 3392 Good (0x00000000) 11:56:06:871 >>>>>> ------ C 291 3028654153 4 CloseSecureChannelRequest s= 29 11:56:06:883 >>>>>> ------ C 292 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:06:891 >>>>>> ------ C 293 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:06:901 >>>>>> ------ C 294 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:08:426 <<<<<< ------ C 292 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:08:427 >>>>>> ------ C 292 3028654154 2 GetEndpointsRequest s= 70 11:56:08:430 >>>>>> ------ C 295 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:09:933 <<<<<< ------ C 293 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:09:935 >>>>>> ------ C 293 3028654155 2 GetEndpointsRequest s= 70 11:56:09:941 >>>>>> ------ C 296 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:11:440 <<<<<< ------ C 294 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:11:441 >>>>>> ------ C 294 3028654156 2 GetEndpointsRequest s= 70 11:56:11:448 <<<<<< ------ C 292 3028654154 2 GetEndpointsResponse s= 3392 Good (0x00000000) Client connected, node: PLC S7-1500 WRITE Create session for node: PLC S7-1500 WRITE 11:56:11:450 >>>>>> ------ C 292 3028654154 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392 11:56:11:466 <<<<<< ------ C 293 3028654155 2 GetEndpointsResponse s= 3392 Good (0x00000000) Client connected, node: PLC S7-1500 WRITE MSG Create session for node: PLC S7-1500 WRITE MSG 11:56:11:467 >>>>>> ------ C 293 3028654155 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392 11:56:11:485 <<<<<< ------ C 294 3028654156 2 GetEndpointsResponse s= 3392 Good (0x00000000) Client connected, node: PLC S7-1500 READ CHOOSEN PROGRAM Create session for node: PLC S7-1500 READ CHOOSEN PROGRAM 11:56:11:486 >>>>>> ------ C 294 3028654156 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392 11:56:12:988 <<<<<< ------ C 295 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:12:988 >>>>>> ------ C 295 3028654157 2 GetEndpointsRequest s= 70 11:56:14:000 <<<<<< ------ C 292 3028654154 3 CreateSessionResponse ns=1;i=2997230216 to:30000ms s= 4796 Good (0x00000000) 11:56:14:003 >>>>>> ------ C 292 3028654154 4 ActivateSessionRequest UserName s= 723 11:56:15:020 <<<<<< ------ C 293 3028654155 3 CreateSessionResponse ns=1;i=3814582517 to:30000ms s= 4796 Good (0x00000000) 11:56:15:024 >>>>>> ------ C 293 3028654155 4 ActivateSessionRequest UserName s= 723 11:56:16:522 <<<<<< ------ C 296 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:16:523 >>>>>> ------ C 296 3028654158 2 GetEndpointsRequest s= 70 Error on create session for node: PLC S7-1500 READ CHOOSEN PROGRAM 15 Sep 13:56:16 - [error] [OpcUa-Client:PLC S7-1500 READ CHOOSEN PROGRAM] Client node error on: PLC S7-1500 READ CHOOSEN PROGRAM error: ["PLC S7-1500 READ CHOOSEN PROGRAM OPC UA connection error: ClientTCP_transport294: socket has been disconnected by third party"] 11:56:16:541 <<<<<< ------ C 295 3028654157 2 GetEndpointsResponse s= 3392 Good (0x00000000) Client connected, node: PLC S7-1500 READ MACHINE STATUS Create session for node: PLC S7-1500 READ MACHINE STATUS 11:56:16:542 >>>>>> ------ C 295 3028654157 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392 11:56:17:144 <<<<<< ------ C 292 3028654154 4 ActivateSessionResponse s= 68 Good (0x00000000) Session created for node: PLC S7-1500 WRITE 11:56:17:755 <<<<<< ------ C 293 3028654155 4 ActivateSessionResponse s= 68 Good (0x00000000) Session created for node: PLC S7-1500 WRITE MSG 11:56:17:762 <<<<<< ------ C 296 3028654158 2 GetEndpointsResponse s= 3392 Good (0x00000000) Client connected, node: PLC S7-1500 SUBSCRIPTION Create session for node: PLC S7-1500 SUBSCRIPTION 11:56:17:763 >>>>>> ------ C 296 3028654158 3 CreateSessionRequest ClientSession1 to:300000ms s= 1392 11:56:18:785 <<<<<< ------ C 295 3028654157 3 CreateSessionResponse ns=1;i=2315717238 to:30000ms s= 4796 Good (0x00000000) 11:56:18:789 >>>>>> ------ C 295 3028654157 4 ActivateSessionRequest UserName s= 723 11:56:19:809 <<<<<< ------ C 296 3028654158 3 CreateSessionResponse ns=1;i=1648881698 to:30000ms s= 4796 Good (0x00000000) 11:56:19:817 >>>>>> ------ C 296 3028654158 4 ActivateSessionRequest UserName s= 723 11:56:19:819 >>>>>> ------ C 297 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 11:56:20:426 <<<<<< ------ C 295 3028654157 4 ActivateSessionResponse s= 68 Good (0x00000000) Session created for node: PLC S7-1500 READ MACHINE STATUS 11:56:21:029 <<<<<< ------ C 296 3028654158 4 ActivateSessionResponse s= 68 Good (0x00000000) Session created for node: PLC S7-1500 SUBSCRIPTION 11:56:21:164 >>>>>> ------ C 296 3028654158 5 CreateSubscriptionRequest s= 56 11:56:22:544 <<<<<< ------ C 297 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 11:56:22.545Z :client_secure_channel_layer :236 requestData not found for requestId = 3 try with 4 11:56:22.545Z :client_secure_channel_layer :241 message was 2:
15 Sep 13:56:22 - [red] Uncaught Exception: 15 Sep 13:56:22 - [error] TypeError: Cannot read properties of undefined (reading 'callback') at MessageBuilder. (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:243:42) at MessageBuilder.emit (node:events:513:28) at MessageBuilder._report_error (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:128:14) at MessageBuilder._feed_messageChunk (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:193:22) at PacketAssembler. (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:64:66) at PacketAssembler.emit (node:events:513:28) at PacketAssembler.feed (/usr/src/node-red/node_modules/node-opcua-packet-assembler/dist/packet_assembler.js:75:18) at MessageBuilder.feed (/usr/src/node-red/node_modules/node-opcua-transport/dist/source/message_builder_base.js:94:35) at ClientSecureChannelLayer._on_receive_message_chunk (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:964:29) at ClientTCP_transport. (/usr/src/node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:809:18) Only this nodered instance is active on the server.
It is possible that "old" sessions of the same container are left on the server? How I can close a session probably? This problem occurs in most cases right after deploying in nodeRed or sometimes during running of the program.
— Reply to this email directly, view it on GitHub https://github.com/mikakaraila/node-red-contrib-opcua/issues/608#issuecomment-1721163807, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABHRYDARCZEGFOY2NODJC63X2Q725ANCNFSM6AAAAAA4XXU22E . You are receiving this because you commented.Message ID: @.***>
So, I was able to "fix" some issues with our flows, and this also increased stability of the program a little bit:
- Reduce number of active sessions by inject multiple write requests in one OPC UA node and sort results afterwards.
- Deploy changed nodes only (so no additional sessions are created after deploying)
But I was not able to figure out the following errors in the log. Perhaps you can give me a short explanation as start point for fixing?
05:34:51:514 <<<<<< ------ C 11186 3028666673 5 ServiceFault s= 24 BadNoSubscription (0x80790000)
I am using a subscription in our program. And this is working fine.
[
{
"id": "ed5e57dbd4d27c1c",
"type": "OpcUa-Client",
"z": "83568dd65a418a7b",
"endpoint": "9afb88462bcc3340",
"action": "subscribe",
"deadbandtype": "a",
"deadbandvalue": 1,
"time": "2",
"timeUnit": "s",
"certificate": "l",
"localfile": "/data/client_certificate.pem",
"localkeyfile": "/data/private_key.pem",
"securitymode": "None",
"securitypolicy": "None",
"folderName4PKI": "",
"useTransport": false,
"maxChunkCount": "",
"maxMessageSize": "",
"receiveBufferSize": "",
"sendBufferSize": "",
"name": "PLC S7-1500 SUBSCRIPTION",
"x": 530,
"y": 160,
"wires": [
[
"f2fd7b8407f9c030",
"aba332f093162776"
]
]
},
{
"id": "3045759ed014f25a",
"type": "function",
"z": "83568dd65a418a7b",
"name": "set topic array",
"func": "msg.topic = 'multiple';\nmsg.payload = [\n { nodeId: 'ns=3;s=\"ACTIVATE_LOAD_1\".\"Confirmation_ID\";datatype=\"string\"' },\n { nodeId: 'ns=3;s=\"ACTIVATE_LOAD_2\".\"Confirmation_ID\";datatype=\"string\"' }\n]\nreturn msg;",
"outputs": 1,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 300,
"y": 160,
"wires": [
[
"ed5e57dbd4d27c1c"
]
]
},
{
"id": "aca1669102f4017a",
"type": "inject",
"z": "83568dd65a418a7b",
"name": "",
"props": [
{
"p": "payload"
},
{
"p": "topic",
"vt": "str"
}
],
"repeat": "",
"crontab": "",
"once": true,
"onceDelay": "30",
"topic": "",
"payload": "",
"payloadType": "date",
"x": 130,
"y": 160,
"wires": [
[
"3045759ed014f25a"
]
]
},
{
"id": "9afb88462bcc3340",
"type": "OpcUa-Endpoint",
"endpoint": "${OPCUAAdress}",
"secpol": "Basic256Sha256",
"secmode": "Sign",
"none": false,
"login": true,
"usercert": false,
"usercertificate": "",
"userprivatekey": ""
}
]
05:34:35:002 <<<<<< ------ C 11176 3028666663 17 ServiceFault s= 24 BadSessionIdInvalid (0x80250000)
I have no idea...
05:34:05:004 <<<<<< ------ C 11176 3028666663 16 ServiceFault s= 24 BadSessionNotActivated (0x80270000)
18 Sep 07:34:05 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: serviceResult = BadSessionNotActivated (0x80270000)"]
In the READ MACHINE STATUS session I am reading multiple registers with a readmultiple action. Here I have also not idea was could be wrong. The flow works...
Could it be misspelled datatype? Try string => String
NOTE: You can use one client node and msg.action = "write" etc. to use different actions with one session.
I tried to modify the datatype name to String and also to remove it completely from the subscription topic. Both did not change the error in the log.
Check server diagnostics with UaExpert. For me it seems that server is out of sessions as error is "Session is not activated".
Are you injecting read/write with interval? Is it too fast?
Subscription should be injected once.
I checkt the number of sessions with UaExpert. The NodeRED app has 3 active sessions plus the one active session for UaExpert. The maximum for the PLC is 4.
The session which causes the BadSessionNotActivated error reads three registers every 30 seconds.
05:25:21:667 >>>>>> ------ C 2638 3028670020 55 ReadRequest nodesToRead.length =1 s= 92
19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Invalid message header detected"]
05:25:21:677 >>>>>> ------ C 2638 3028670020 56 ReadRequest nodesToRead.length =1 s= 88
19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Connection Break"]
19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Invalid Channel BadConnectionClosed"]
05:25:21:695 >>>>>> ------ C 2654 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81
05:25:23:209 <<<<<< ------ C 2654 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000)
05:25:23:212 >>>>>> ------ C 2654 3028670036 2 ActivateSessionRequest UserName s= 723
05:25:23:213 <<<<<< ------ C 2643 3028670025 47 PublishResponse seq#=23 s= 65 Good (0x00000000)
05:25:23:213 >>>>>> ------ C 2643 3028670025 53 PublishRequest 312000ms s= 38
05:25:23:818 <<<<<< ------ C 2654 3028670036 2 ActivateSessionResponse s= 68 Good (0x00000000)
05:25:29:209 <<<<<< ------ C 2643 3028670025 48 PublishResponse seq#=23 s= 65 Good (0x00000000)
05:25:29:209 >>>>>> ------ C 2643 3028670025 54 PublishRequest 312000ms s= 38
05:25:35:210 <<<<<< ------ C 2643 3028670025 49 PublishResponse seq#=23 s= 65 Good (0x00000000)
05:25:35:211 >>>>>> ------ C 2643 3028670025 55 PublishRequest 312000ms s= 38
05:25:41:209 <<<<<< ------ C 2643 3028670025 50 PublishResponse seq#=23 s= 65 Good (0x00000000)
05:25:41:210 >>>>>> ------ C 2643 3028670025 56 PublishRequest 312000ms s= 38
05:25:47:208 <<<<<< ------ C 2643 3028670025 51 PublishResponse seq#=23 s= 65 Good (0x00000000)
05:25:47:209 >>>>>> ------ C 2643 3028670025 57 PublishRequest 312000ms s= 38
What could cause the Invalid message header detected log?
Here is the flow which is creating the PLC S7-1500 READ MACHINE STATUS session:
[
{
"id": "7355dd045f1b8b2e",
"type": "inject",
"z": "82ba9aca03ad156b",
"name": "",
"props": [],
"repeat": "30",
"crontab": "",
"once": true,
"onceDelay": "120",
"topic": "",
"x": 290,
"y": 180,
"wires": [
[
"c2452c5c5344d11c",
"3540eabae9e61a33",
"a6cc6838c71e45db"
]
]
},
{
"id": "a6cc6838c71e45db",
"type": "OpcUa-Item",
"z": "82ba9aca03ad156b",
"item": "ns=3;s=\"CTRL_DATA\".\"Stage_Temper_Actual\"",
"datatype": "Int16",
"value": "",
"name": "stage_temper_actual",
"x": 760,
"y": 380,
"wires": [
[
"5a9e4414c60afd8e"
]
]
},
{
"id": "3540eabae9e61a33",
"type": "OpcUa-Item",
"z": "82ba9aca03ad156b",
"item": "ns=3;s=\"MACHINE\".\"STATE\"",
"datatype": "Int8",
"value": "",
"name": "machine_state",
"x": 740,
"y": 280,
"wires": [
[
"5a9e4414c60afd8e"
]
]
},
{
"id": "c2452c5c5344d11c",
"type": "OpcUa-Item",
"z": "82ba9aca03ad156b",
"item": "ns=3;s=\"MACHINE\".\"AUTOMATIC\"",
"datatype": "Boolean",
"value": "",
"name": "machine_automatic",
"x": 750,
"y": 160,
"wires": [
[
"5a9e4414c60afd8e"
]
]
},
{
"id": "5a9e4414c60afd8e",
"type": "OpcUa-Client",
"z": "82ba9aca03ad156b",
"endpoint": "9afb88462bcc3340",
"action": "read",
"deadbandtype": "a",
"deadbandvalue": 1,
"time": "10",
"timeUnit": "s",
"certificate": "l",
"localfile": "/data/client_certificate.pem",
"localkeyfile": "/data/private_key.pem",
"securitymode": "None",
"securitypolicy": "None",
"folderName4PKI": "",
"useTransport": false,
"maxChunkCount": "",
"maxMessageSize": "",
"receiveBufferSize": "",
"sendBufferSize": "",
"name": "PLC S7-1500 READ MACHINE STATUS",
"x": 1160,
"y": 160,
"wires": [
[
"963908e1786ddbd9",
"b37177da10fa2de4"
]
]
},
{
"id": "963908e1786ddbd9",
"type": "debug",
"z": "82ba9aca03ad156b",
"name": "MachineStatus raw",
"active": true,
"tosidebar": true,
"console": false,
"tostatus": false,
"complete": "true",
"targetType": "full",
"statusVal": "",
"statusType": "auto",
"x": 1430,
"y": 60,
"wires": []
},
{
"id": "9afb88462bcc3340",
"type": "OpcUa-Endpoint",
"endpoint": "${OPCUAAdress}",
"secpol": "Basic256Sha256",
"secmode": "Sign",
"none": true,
"login": true,
"usercert": false,
"usercertificate": "",
"userprivatekey": ""
}
]
You're using single read with 3 items... Use read multiple, take a look to OPC-UA-TEST-NODES.json example.
On Tue, Sep 19, 2023, 08:29 nico @.***> wrote:
I checkt the number of sessions with UaExpert. The NodeRED app has 3 active sessions plus the one active session for UaExpert. The maximum for the PLC is 4.
The session which causes the BadSessionNotActivated error reads three registers every 30 seconds.
05:25:21:667 >>>>>> ------ C 2638 3028670020 55 ReadRequest nodesToRead.length =1 s= 92 19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Invalid message header detected"] 05:25:21:677 >>>>>> ------ C 2638 3028670020 56 ReadRequest nodesToRead.length =1 s= 88 19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Connection Break"] 19 Sep 07:25:21 - [error] [OpcUa-Client:PLC S7-1500 READ MACHINE STATUS] Client node error on: PLC S7-1500 READ MACHINE STATUS error: ["PLC S7-1500 READ MACHINE STATUS error at active reading: Invalid Channel BadConnectionClosed"] 05:25:21:695 >>>>>> ------ C 2654 0 1 OpenSecureChannelRequest Issue Sign lt:200000ms s= 81 05:25:23:209 <<<<<< ------ C 2654 0 1 OpenSecureChannelResponse s= 84 Good (0x00000000) 05:25:23:212 >>>>>> ------ C 2654 3028670036 2 ActivateSessionRequest UserName s= 723 05:25:23:213 <<<<<< ------ C 2643 3028670025 47 PublishResponse seq#=23 s= 65 Good (0x00000000) 05:25:23:213 >>>>>> ------ C 2643 3028670025 53 PublishRequest 312000ms s= 38 05:25:23:818 <<<<<< ------ C 2654 3028670036 2 ActivateSessionResponse s= 68 Good (0x00000000) 05:25:29:209 <<<<<< ------ C 2643 3028670025 48 PublishResponse seq#=23 s= 65 Good (0x00000000) 05:25:29:209 >>>>>> ------ C 2643 3028670025 54 PublishRequest 312000ms s= 38 05:25:35:210 <<<<<< ------ C 2643 3028670025 49 PublishResponse seq#=23 s= 65 Good (0x00000000) 05:25:35:211 >>>>>> ------ C 2643 3028670025 55 PublishRequest 312000ms s= 38 05:25:41:209 <<<<<< ------ C 2643 3028670025 50 PublishResponse seq#=23 s= 65 Good (0x00000000) 05:25:41:210 >>>>>> ------ C 2643 3028670025 56 PublishRequest 312000ms s= 38 05:25:47:208 <<<<<< ------ C 2643 3028670025 51 PublishResponse seq#=23 s= 65 Good (0x00000000) 05:25:47:209 >>>>>> ------ C 2643 3028670025 57 PublishRequest 312000ms s= 38
What could cause the Invalid message header detected log?
Here is the flow which is creating the PLC S7-1500 READ MACHINE STATUS session:
[ { "id": "7355dd045f1b8b2e", "type": "inject", "z": "82ba9aca03ad156b", "name": "", "props": [], "repeat": "30", "crontab": "", "once": true, "onceDelay": "120", "topic": "", "x": 290, "y": 180, "wires": [ [ "c2452c5c5344d11c", "3540eabae9e61a33", "a6cc6838c71e45db" ] ] }, { "id": "a6cc6838c71e45db", "type": "OpcUa-Item", "z": "82ba9aca03ad156b", "item": "ns=3;s="CTRL_DATA"."Stage_Temper_Actual"", "datatype": "Int16", "value": "", "name": "stage_temper_actual", "x": 760, "y": 380, "wires": [ [ "5a9e4414c60afd8e" ] ] }, { "id": "3540eabae9e61a33", "type": "OpcUa-Item", "z": "82ba9aca03ad156b", "item": "ns=3;s="MACHINE"."STATE"", "datatype": "Int8", "value": "", "name": "machine_state", "x": 740, "y": 280, "wires": [ [ "5a9e4414c60afd8e" ] ] }, { "id": "c2452c5c5344d11c", "type": "OpcUa-Item", "z": "82ba9aca03ad156b", "item": "ns=3;s="MACHINE"."AUTOMATIC"", "datatype": "Boolean", "value": "", "name": "machine_automatic", "x": 750, "y": 160, "wires": [ [ "5a9e4414c60afd8e" ] ] }, { "id": "5a9e4414c60afd8e", "type": "OpcUa-Client", "z": "82ba9aca03ad156b", "endpoint": "9afb88462bcc3340", "action": "read", "deadbandtype": "a", "deadbandvalue": 1, "time": "10", "timeUnit": "s", "certificate": "l", "localfile": "/data/client_certificate.pem", "localkeyfile": "/data/private_key.pem", "securitymode": "None", "securitypolicy": "None", "folderName4PKI": "", "useTransport": false, "maxChunkCount": "", "maxMessageSize": "", "receiveBufferSize": "", "sendBufferSize": "", "name": "PLC S7-1500 READ MACHINE STATUS", "x": 1160, "y": 160, "wires": [ [ "963908e1786ddbd9", "b37177da10fa2de4" ] ] }, { "id": "963908e1786ddbd9", "type": "debug", "z": "82ba9aca03ad156b", "name": "MachineStatus raw", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 1430, "y": 60, "wires": [] }, { "id": "9afb88462bcc3340", "type": "OpcUa-Endpoint", "endpoint": "${OPCUAAdress}", "secpol": "Basic256Sha256", "secmode": "Sign", "none": true, "login": true, "usercert": false, "usercertificate": "", "userprivatekey": "" } ]
— Reply to this email directly, view it on GitHub https://github.com/mikakaraila/node-red-contrib-opcua/issues/608#issuecomment-1724853284, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABHRYDG55E7A6BEDBZ73YCTX3EUSDANCNFSM6AAAAAA4XXU22E . You are receiving this because you commented.Message ID: @.***>
I used read multiple before and this leads to more error messages and more instability of the container. Any ideas what is the reason for the Invalid message header detected could be?
I tested single read with UaExpert, here is modified flow file. Your flow don´t actually inject empty payload/topic, only msg object.
[{"id":"29df21a6a988eea5","type":"tab","label":"Flow 1","disabled":false,"info":"","env":[]},{"id":"9afb88462bcc3340","type":"OpcUa-Endpoint","endpoint":"${OPCUAAdress}","secpol":"Basic256Sha256","secmode":"Sign","none":true,"login":true,"usercert":false,"usercertificate":"","userprivatekey":""},{"id":"4272cd8839fa19d1","type":"OpcUa-Endpoint","endpoint":"opc.tcp://H7Q8Q13.mshome.net:53530/OPCUA/SimulationServer","secpol":"None","secmode":"None","none":true,"login":false,"usercert":false,"usercertificate":"","userprivatekey":""},{"id":"7355dd045f1b8b2e","type":"inject","z":"29df21a6a988eea5","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"30","crontab":"","once":true,"onceDelay":"120","topic":"","payloadType":"str","x":290,"y":180,"wires":[["c2452c5c5344d11c","3540eabae9e61a33","a6cc6838c71e45db"]]},{"id":"a6cc6838c71e45db","type":"OpcUa-Item","z":"29df21a6a988eea5","item":"ns=3;s=\"CTRL_DATA\".\"Stage_Temper_Actual\"","datatype":"Int16","value":"","name":"stage_temper_actual","x":760,"y":380,"wires":[["5a9e4414c60afd8e"]]},{"id":"3540eabae9e61a33","type":"OpcUa-Item","z":"29df21a6a988eea5","item":"ns=3;s=\"MACHINE\".\"STATE\"","datatype":"Int8","value":"","name":"machine_state","x":740,"y":280,"wires":[["5a9e4414c60afd8e"]]},{"id":"c2452c5c5344d11c","type":"OpcUa-Item","z":"29df21a6a988eea5","item":"ns=3;s=\"MACHINE\".\"AUTOMATIC\"","datatype":"Boolean","value":"","name":"machine_automatic","x":750,"y":160,"wires":[["5a9e4414c60afd8e"]]},{"id":"5a9e4414c60afd8e","type":"OpcUa-Client","z":"29df21a6a988eea5","endpoint":"9afb88462bcc3340","action":"read","deadbandtype":"a","deadbandvalue":1,"time":"10","timeUnit":"s","certificate":"l","localfile":"/data/client_certificate.pem","localkeyfile":"/data/private_key.pem","securitymode":"None","securitypolicy":"None","folderName4PKI":"","useTransport":false,"maxChunkCount":"","maxMessageSize":"","receiveBufferSize":"","sendBufferSize":"","name":"PLC S7-1500 READ MACHINE STATUS","x":1160,"y":160,"wires":[["963908e1786ddbd9"]]},{"id":"963908e1786ddbd9","type":"debug","z":"29df21a6a988eea5","name":"MachineStatus raw","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":1490,"y":160,"wires":[]},{"id":"49b4bfbeb7744537","type":"OpcUa-Client","z":"29df21a6a988eea5","endpoint":"4272cd8839fa19d1","action":"read","deadbandtype":"a","deadbandvalue":1,"time":10,"timeUnit":"s","certificate":"n","localfile":"","localkeyfile":"","securitymode":"None","securitypolicy":"None","folderName4PKI":"","useTransport":false,"maxChunkCount":1,"maxMessageSize":8192,"receiveBufferSize":8192,"sendBufferSize":8192,"name":"","x":1090,"y":480,"wires":[["504770824cc567ca"]]},{"id":"a386a7d983ad5fd7","type":"OpcUa-Item","z":"29df21a6a988eea5","item":"ns=3;i=1001","datatype":"Double","value":"","name":"Counter","x":720,"y":480,"wires":[["49b4bfbeb7744537"]]},{"id":"504770824cc567ca","type":"debug","z":"29df21a6a988eea5","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":1450,"y":480,"wires":[]},{"id":"4578f9c7a84a5290","type":"inject","z":"29df21a6a988eea5","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"10","crontab":"","once":true,"onceDelay":"1","topic":"","payloadType":"str","x":270,"y":480,"wires":[["a386a7d983ad5fd7","e8aea9561405a779"]]},{"id":"e8aea9561405a779","type":"OpcUa-Item","z":"29df21a6a988eea5","item":"ns=3;i=1002","datatype":"Double","value":"","name":"Random","x":720,"y":540,"wires":[["49b4bfbeb7744537"]]}]
MMhh.. We still have the serviceResult = BadSessionNotActivated (0x80270000)"] issue sometime in the multi read session. This leads also to a instability of the running nodered instance.
Any ideas for further investigation? Thanks!
Have you checked how many session are active? I expect your server will run occasionally out of sessions. Reading is always "heavy" action for PLC CPU, could be also some task / execution problem.
@buhln Hi buhln, trying to reach you personally, but there was no social profile/ message window on your GitHub profile. Let me tell you about myself, i am a new internee in my automation company and dealing in IoT field. But since I'm a newbie, and not from a programming background, I get occasionally stuck. If you are available for some kind of guidance from time to time, it would be really helpful for me.
Hmm what else is done inside flow? Debug messages can block sometimes execution or save data to DB if they are not asynchronous. Or embedded OPC UA server is not responding as it must run real-time control.
Have tested with subscription?
I updated NodeRed to version 4.0.1 and the opcua package to 0.2.329. Now it looks like that the issues are gone.