uncatchable error on read client

JoeZeng133 commented 4 years ago

trying to read a tag that does not exist on the OPC UA server. It logs the error to the debug console, but the catch node does not catch it. Below is the simple flow to generate this issue.

JoeZeng133 commented 4 years ago

btw, the error message comes from this line (if I comment it out, the error message disappears). hope it helps https://github.com/mikakaraila/node-red-contrib-opcua/blob/5a2e86896150a8b931b0d2c0be5a7aed82e16c59/opcua/102-opcuaclient.js#L566

mikakaraila commented 4 years ago

Yes, caused by dataValue === null or undefined then it will crash on accessing DataType[]. Actually I have removed similar snippet from other part, so I removed this one also.

mikakaraila commented 4 years ago

OK test with 0.2.86

EliasReuter commented 3 years ago

Hi @mikakaraila and @JoeZeng133

I am running a flow reading almost 500 variables on the version 0.2.89 of the node and still have the same problem, an its not logging "where" the problem occurs. It is Blank, compared to Joe's screenshot, where it describe that the problem comes from the "Read" function. We are currently using the "Read Multiple" Function, but used to use the "Read" function. The problem occurred in both cases.

Is it possible that there is still an issue with this line that Joe found? Is it possible that this could lead to restart every ~10/15mins of the node red service? (I can open a new issue regarding to this unexpected restarts if prefered, but mentioning this issue, cause it may be a possible cause)

Thank you!

mikakaraila commented 3 years ago

Ok, I will take a look, but most probably not on this week. Bit busy at work...

EliasReuter commented 3 years ago

Hi @mikakaraila Thank you for the support.

Just to add some more info, before this mentioned error shows up, this message appears:

(Not sure if there's a direct relation between these errors, but it might be useful for you in order to debug)

mikakaraila commented 3 years ago

I check code and somehow it seems to relate to connection is lost and node.client is null.

I need more info why connection is broken. Any messages on server side?

This issue has changed, error in now on different part of code, not in the original place as in the title. Reading 500 variables will cause load on server side, subscribe is more efficient.

rcarreir commented 3 years ago

Hi @mikakaraila ! I am having the same issue as @EliasReuter, but in my case there are just a few variables (less than 40) and the "OPC UA Client” stucks at some point and only gets back to work again after resetting the whole flow. I can't understand what the problem is, but as the entire flow crashes my variables stops to upload to my server. I think in this case subscribe may not be the best option.

In parallel, while I was writing down this comment I found another error in the node labeled as "invalid endpoint" and checking the server status in "UAExpert", I am able to see that the OPC server shut down for some time and after going online and working again, the node still gets stuck at that error and only goes back to active reading after resetting the flow. So, it seems that the node has no auto reset or auto reconnect after an OPC server error.

nodered

UaExpert

Thanks for your support!

Regards, Rodrigo

mikakaraila commented 3 years ago

Etienne fixed most probably something related to this today

EliasReuter commented 3 years ago

Hi @mikakaraila,

1) "I check code and somehow it seems to relate to connection is lost and node.client is null. I need more info why connection is broken. Any messages on server side?"

We are connection to a Matrikon OPC UA Wrapper Server that is connecting to a SCADA system via OPC DA. Following, description and screenshots of what we are using: (+ log files)

Driver OIGatteway Wonderware

Driver Matrikon OPC US/DA

Servidor OPC

Log files from wrapper MatrikonOpcUaWrapper20201005-0040.log.zip

Hope this is useful information for you

2) "This issue has changed, error in now on different part of code, not in the original place as in the title."

Ok. Any other information you need us to provide you in order to find the bug?

3) "Reading 500 variables will cause load on server side, subscribe is more efficient."

Our application needs to get the value of these 500 variables in order to send them in jsons to other system with https, where deterministic interval between every measure is needed. (Even if value is the same) So we think subscription is not what would apply to our needs. So "Inject Interval + MultipleRead" seems to be the best solution at the time for us. But we are open to suggestions.

Thank you!

mikakaraila commented 3 years ago

I have a feeling that my client can disconnect if response time is longer than session timeout. Can you check how much time from the inject (get all 500 variables) it will take time until client gets values? Sometimes server cannot collect data and build message immediately as it will run also control actions.

And what is inject inteval? It can be also close to session timeout and together they can causes the fact that session is closed.

EliasReuter commented 3 years ago

Hi @mikakaraila,

Thank you for the Support!

Reading method: READMULTIPLE ~ 80% of the variables

Inject Interval = 5 seconds
Time between values = 4 to 6 seconds with inconsistencies up to 10 seconds (description)

Reading method: READMULTIPLE ~ 20% of the variables

Inject Interval = 15 seconds
Time between values = 4 to 6 seconds with inconsistencies up to 10 seconds (description)

What do you mean by "control actions"? Writing? We are only reading values. This Matrikon OPC UA Wrapper is dedicated to read values from node red

Inconsistency problem I was thinking in opening a new issue for this after this progresses, but it seems to be related, after your question (but if prefered we can open an new issue an refer to this one) We have an non-deterministic interval between measures as described above. Around 70% of the time the values are equal-distance, but then some "lakes" may appear, that are caused because the read (or read multiple) action is taking longer than "immediate" read. Even up to 10 to 20 seconds without response.

Here is an graph we made to show this behavior: The points at the left is showing how there is an value every ~5 seconds , but then an lake of ~10 or ~20 seconds appears with no data (we check that this non-deterministic interval between values is caused by the delay of the read action in the opc ua client as comment. we located that problem surrounding the node with debug nodes)

Hope this is information is useful for you and even related to this issue. But if needed, we can open an new issue related to this (or once its solved, for future visitors).

Thank you, mika!

mikakaraila commented 3 years ago

OK, my feeling was correct, client uses 10s session timeout:

    node.session.timeout = opcuaBasics.calc_milliseconds_by_time_and_unit(10, "s");

It should be 60s or even 5min so it will not disconnect and go to re-connect loop. Will you change it and test before I modify it? File: 102-opcuaclient.js line 410.

EliasReuter commented 3 years ago

Hi @mikakaraila,

I changed that line in the mentioned file, first to (60, "s") and then to (300, "s"), and restarted NodeRed Service (in order to make sure it takes the updated js). But I still get the same error.

Am I forgetting something to test this right? What else can I test for you?

mikakaraila commented 3 years ago

Ack, I will study bit more. It can be that timeout is set in wrong place.

mikakaraila commented 3 years ago

Try this, same file and look line numbers:

EliasReuter commented 3 years ago

Hi @mikakaraila,

If I copy those lines, "timeout" (line 139 in your image) is an undefined variable in my context. Client Node doesn't even shows connection status and following error shows up: (i guess its not working at all with this error)

So, I commented the line where timeout variable is assigned, leaving the following:

With this, same error of this issue appears after a while.

Where and how should I define that timeout variable? Are you using it somewhere else before or after that image? If preferred, sent me the complete "102-opcuaclient.js" file and I'll replace it in my environment (I'll back up the original one), in order to test your fixes.

Thank you 👍

mikakaraila commented 3 years ago

Just testing, library uses for some reason 60s timeout, trying to solve it now:

mikakaraila commented 3 years ago

I expect Prosys UA Simulation server decides this. I request it to be 300s == 5min but server limits session timeout to 60s. Rename .txt to .js and test again.

102-opcuaclient.txt

EliasReuter commented 3 years ago

Renamed the original file to "102-opcuaclient_old.js" and got this new "102-opcuaclient.js" you sent me.

After restarting node red service by "sudo systemctl restart nodered.service" same message appears:

mikakaraila commented 3 years ago

Then the problem is not in the session timeout. I need more debug output. Can you get console output from the node-red?

https://discourse.nodered.org/t/where-can-i-read-node-red-logs/7698

EliasReuter commented 3 years ago

Hi, Following status appears now:

Node Red's log files:

mikakaraila commented 3 years ago

Log files missing...

EliasReuter commented 3 years ago

logNodeRedForOpc.txt logNodeRedForOpc1.txt logNodeRedForOpc2.txt logNodeRedForOpc3.txt

EliasReuter commented 3 years ago

logNodeRedForOpcUa.txt

mikakaraila commented 3 years ago

OK I will study these:

18 Dec 11:18:31 - [error] [OpcUa-Client:f5b707d4.9b7e1] Client node error on: dispose when pendingTransactions is not empty

xxxxx <<<<<< _on_message_received for unknown or timeout request 8 ServiceFault BadSessionIdInvalid (0x80250000) 1524777

18 Dec 11:18:47 - [error] [OpcUa-Client:f5b707d4.9b7e1] Client node error on: dispose when pendingTransactions is not empty xxxxx <<<<<< _on_message_received for unknown or timeout request 9 ServiceFault BadSessionIdInvalid (0x80250000) 1524772

Then it stays: dispose when pendingTransactions is not empty dispose when pendingTransactions is not empty dispose when pendingTransactions is not empty dispose when pendingTransactions is not empty dispose when pendingTransactions is not empty dispose when pendingTransactions is not empty

mikakaraila commented 3 years ago

Found one new one: 18 Dec 11:19:48 - [error] [OpcUa-Client:d7233715.316068] Client node error on: ERROR !!! callback has thrown en error Error at Object.assert (/home/ldc/.node-red/node_modules/node-opcua-assert/dist/index.js:13:21) at /home/ldc/.node-red/node_modules/node-opcua-client/dist/private/client_base_impl.js:414:45 at ClientSecureChannelLayer. (/home/ldc/.node-red/node_modules/node-opcua-client/dist/private/client_base_impl.js:575:24) at Object.modified_callback [as callback] (/home/ldc/.node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:953:31) at ClientSecureChannelLayer.cancelPendingTransactions (/home/ldc/.node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:401:29) at ClientSecureChannelLayer.close (/home/ldc/.node-red/node_modules/node-opcua-secure-channel/dist/source/client/client_secure_channel_layer.js:419:14) at OPCUAClientImpl.disconnect (/home/ldc/.node-red/node_modules/node-opcua-client/dist/private/client_base_impl.js:691:24) at OPCUAClientImpl.disconnect (/home/ldc/.node-red/node_modules/thenify/index.js:65:46) at OPCUAClientImpl.disconnect (/home/ldc/.node-red/node_modules/thenify/index.js:65:46) at close_opcua_client (/home/ldc/.node-red/node_modules/node-red-contrib-opcua/opcua/102-opcuaclient.js:307:21) 18 Dec 11:19:48 - [error] [OpcUa-Client:d7233715.316068] Client node error on:

mikakaraila commented 3 years ago

Client cannot disconnect before all transactions has been finished.

How are you storing data?

EliasReuter commented 3 years ago

Hi @mikakaraila,

There is no storage in Node-Red. In Node-Red, once I've got the values for the OPC UA Tags I build a new JSON (variable_id + value + timestamp) and send it to a web service via https from node red. So, there is no storage from Node Red Side (only a few global/flow variables with frequent dumps into files to avoid nulls and errors when NodeRed restarts as I mentioned before in this thread, maybe caused by the error of this issue).

There is no storage at the Server Side. As I've mentioned, the Matrikon OPC UA Wrapper Server that is connecting to a SCADA system (Wonderware Archestra) via OPC DA and providing us with variables via OPC UA.

I'm not sure if I answered your question with this. If not, what do you mean by "How are you storing data?". How and why could storage strategies affect the performance of OPC UA connectivity/session?

mikakaraila commented 3 years ago

I was just expecting if storing values takes long time or it is more than 10s it could causes problems if it blocks client.

Storing values to JSON files can cause something... couple of checks: 1) Check save value time if it is more than 10s 2) Check server session count with UaExpert server diagnostics will it incease?

After that we could perhaps modify flow to read values again after 10s values are saved. If interval is too fast then it could cause queue of read values and later crash flow.

EliasReuter commented 3 years ago

Hi @mikakaraila,

The flow is not saving into JSON Files, just building the object in a function node and then sending it via https, as I described. No storing action but those context variables from node red.

I edited every inject node with "ReadMultiple" action to 20seconds, to test what you are saying, but the messages appears either way. So maybe fast interval is not the case?

It's not so easy for me at the moment to install UaExpert Server Diagnostics in that Computer, but I can give it a try if it's really needed.

Should I still use your .js file? or should i get back to the original?

mikakaraila commented 3 years ago

Follow first CurrentSessionCount:

I will do some other investigation what will happen with read & session timeout with different parameters.

mikakaraila commented 3 years ago

OK, I found two places and added error handling. I got error repeated by deploying flow again.

Seems to continue, I will run more tests, but at least not crashing anymore: 22 Dec 22:31:19 - [warn] [OpcUa-Item:c7d7e4aa.ee8468] OpcUaClientNode: Setting value to dispose when pendingTransactions is not empty 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Session closed 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: session closed 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: closed 22 Dec 22:31:19 - [error] [OpcUa-Client:84353b80.d69fb8] Client node error on: error: " error at active reading: Session has been closed and should not be used to perform a transaction anymore" 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: error 22 Dec 22:31:19 - [warn] [OpcUa-Item:c7d7e4aa.ee8468] OpcUaClientNode: Setting value to 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client disconnected! 22 Dec 22:31:19 - [warn] [OpcUa-Client:84353b80.d69fb8] OpcUaClientNode: Create Client: {"securityPolicy":"http://opcfoundation.org/UA/SecurityPolicy#None","securityMode":1,"requestedSessionTimeout":300000,"applicationName":"","clientName":"","endpoint_must_exist":false,"defaultSecureTokenLifetime":200000,"connectionStrategy":{"maxRetry":10,"initialDelay":5000,"maxDelay":30000},"keepSessionAlive":true,"certificateFile":"C:\\Users\\karaimi\\.node-red\\node_modules\\node-red-contrib-opcua\\node_modules\\node-opcua-client\\certificates\\client_selfsigned_cert_2048.pem","privateKeyFile":"C:\\Users\\karaimi\\.node-red\\node_modules\\node-red-contrib-opcua\\node_modules\\node-opcua-client\\certificates\\PKI\\own\\private\\private_key.pem"} 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: create client 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Connecting to opc.tcp://H7Q8Q13.mshome.net:53530/OPCUA/SimulationServer 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: connecting 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Exact endpointUrl: opc.tcp://H7Q8Q13.mshome.net:53530/OPCUA/SimulationServer hostname: H7Q8Q13 22 Dec 22:31:19 - [warn] [OpcUa-Item:c7d7e4aa.ee8468] OpcUaClientNode: Setting value to 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client disconnected! 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Connected to opc.tcp://H7Q8Q13.mshome.net:53530/OPCUA/SimulationServer 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Connected to opc.tcp://H7Q8Q13.mshome.net:53530/OPCUA/SimulationServer 22 Dec 22:31:19 - [error] [OpcUa-Client:84353b80.d69fb8] Client node error on: error: "Cannot read endpoints: TypeError: Cannot read property 'getEndpoints' of null" 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Create session ... 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Create session with userIdentity: {"userName":"","password":"","type":0} 22 Dec 22:31:19 - [error] [OpcUa-Client:84353b80.d69fb8] Client node error on: error: "Client not yet created, cannot create session" 22 Dec 22:31:19 - [info] [OpcUa-Client:84353b80.d69fb8] Client status: connection error

mikakaraila commented 3 years ago

I just published new version 0.2.90 that contains fixes to error handling. Test it please.

EliasReuter commented 3 years ago

hi @mikakaraila,

I downloaded the new version, but now following error appears after a while (now with information):

mikakaraila commented 3 years ago

What is the first error you will get?

I made new version that will report if client is not created/connected before trying to read endpoints. Update to v0.2.91

s4ke commented 3 years ago

Could it be that the opc ua client is not properly cleaned up and retried if it dies during connection? I tested the following:

Active connection in Node-RED
Killed OPC-UA Server
Tried fetching data via inject node, died with this error: "Client node error on: READ Client for Server error: "READ Client for Server error at active reading: Session has been closed and should not be used to perform a transaction anymore""
Restarted OPC-UA Server, injection does not work anymore

mikakaraila commented 3 years ago

I tested in the same way with Prosys UA Simulator. What server did you use? Client should go to re-connect itself. Is your flow sending inject with interval to read values? What is interval 1s?

I will re-test again, can be some timing problem and thus client is not connecting correctly.

s4ke commented 3 years ago

For this particular test, we used https://github.com/flopach/opc-ua-sensor-simulator

mikakaraila commented 3 years ago

Aah, it is using Free OPCUA (Python based). OK I will use it to test again.

I expect there can be something that perhaps causes re-connect is not working...

mikakaraila commented 3 years ago

Yes, there seems to be something that Python server makes different way...

mikakaraila commented 3 years ago

Seems to be problem to UaExpert also to re-connect to server:

mikakaraila commented 3 years ago

For me problem seems to be somehow inside Python server. I will check & compare this to Prosys UA Simulator how it handles session after server is re-started and old id is used to create session. As you see UaExpert fails to re-connect for the same reason.

As new session is created and then client tries to connect there seems to come error, this causes error in creating connection: ERROR:asyncua.server.uaprocessor:sending service fault response: "The server does not support the requested service." (BadServiceUnsupported)

INFO:asyncua:Starting server! WARNING:asyncua.server.server:Endpoints other than open requested but private key and certificate are not set. INFO:asyncua.server.internal_server:starting internal server INFO:asyncua.server.binary_server_asyncio:Listening on 127.0.0.1:4840 INFO:asyncua.server.binary_server_asyncio:New connection from ('127.0.0.1', 51953) INFO:asyncua.server.uaprocessor:Activate session request (None) INFO:asyncua.server.uaprocessor:request to activate non-existing session (None) ERROR:asyncua.server.uaprocessor:sending service fault response: "The session id is not valid." (BadSessionIdInvalid) INFO:asyncua.server.uaprocessor:Create session request (None) INFO:asyncua.server.internal_session:Created internal session ('127.0.0.1', 51953) INFO:asyncua.server.internal_session:Create session request INFO:asyncua.server.internal_server:get endpoint INFO:asyncua.server.uaprocessor:Activate session request (None) INFO:asyncua.server.internal_session:activate session INFO:asyncua.server.internal_session:Activated internal session ('127.0.0.1', 51953) for user User(role=<UserRole.User: 3>, name=None) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:translate browsepaths to nodeids request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.address_space:element RelativePathElement(ReferenceTypeId:TwoByteNodeId(i=46), IsInverse:False, IncludeSubtypes:True, TargetName:QualifiedName(0:OptionSetValues)) was not found in node FourByteNodeId(i=17588) INFO:asyncua.server.address_space:element RelativePathElement(ReferenceTypeId:TwoByteNodeId(i=46), IsInverse:False, IncludeSubtypes:True, TargetName:QualifiedName(0:OptionSetValues)) was not found in node FourByteNodeId(i=288) INFO:asyncua.server.address_space:element RelativePathElement(ReferenceTypeId:TwoByteNodeId(i=46), IsInverse:False, IncludeSubtypes:True, TargetName:QualifiedName(0:OptionSetValues)) was not found in node FourByteNodeId(i=20998) INFO:asyncua.server.address_space:element RelativePathElement(ReferenceTypeId:TwoByteNodeId(i=46), IsInverse:False, IncludeSubtypes:True, TargetName:QualifiedName(0:OptionSetValues)) was not found in node FourByteNodeId(i=289) INFO:asyncua.server.address_space:element RelativePathElement(ReferenceTypeId:TwoByteNodeId(i=46), IsInverse:False, IncludeSubtypes:True, TargetName:QualifiedName(0:OptionSetValues)) was not found in node FourByteNodeId(i=11737) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Read request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:Browse request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:create subscription request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.subscription_service:create subscription INFO:asyncua.server.uaprocessor:create monitored items request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.subscription_service:create monitored items INFO:asyncua.server.monitored_item_service.78:request to subscribe to events for node FourByteNodeId(i=2253) and attribute 12 INFO:asyncua.server.uaprocessor:create subscription request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.subscription_service:create subscription INFO:asyncua.server.uaprocessor:create monitored items request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.subscription_service:create monitored items INFO:asyncua.server.monitored_item_service.79:request to subscribe to datachange for node FourByteNodeId(ns=2;i=3) and attribute 13 INFO:asyncua.server.monitored_item_service.79:request to subscribe to datachange for node FourByteNodeId(ns=2;i=4) and attribute 13 INFO:asyncua.server.monitored_item_service.79:request to subscribe to datachange for node FourByteNodeId(ns=2;i=2) and attribute 13 INFO:asyncua.server.subscription_service:publish request with acks [] INFO:asyncua.server.subscription_service:publish request with acks [] INFO:asyncua.server.subscription_service:publish request with acks [] INFO:asyncua.server.subscription_service:publish request with acks [] INFO:asyncua.server.subscription_service:publish request with acks [SubscriptionAcknowledgement(SubscriptionId:79, SequenceNumber:1)] INFO:asyncua.server.subscription_service:publish request with acks [SubscriptionAcknowledgement(SubscriptionId:79, SequenceNumber:2)] INFO:asyncua.server.subscription_service:publish request with acks [SubscriptionAcknowledgement(SubscriptionId:79, SequenceNumber:3)] INFO:asyncua.server.binary_server_asyncio:New connection from ('127.0.0.1', 51966) INFO:asyncua.server.uaprocessor:Activate session request (None) INFO:asyncua.server.uaprocessor:request to activate non-existing session (None) ERROR:asyncua.server.uaprocessor:sending service fault response: "The session id is not valid." (BadSessionIdInvalid) INFO:asyncua.server.uaprocessor:Create session request (None) INFO:asyncua.server.internal_session:Created internal session ('127.0.0.1', 51966) INFO:asyncua.server.internal_session:Create session request INFO:asyncua.server.internal_server:get endpoint INFO:asyncua.server.uaprocessor:Activate session request (None) INFO:asyncua.server.internal_session:activate session INFO:asyncua.server.internal_session:Activated internal session ('127.0.0.1', 51966) for user User(role=<UserRole.User: 3>, name=None) WARNING:asyncua.server.uaprocessor:Unknown message received FourByteNodeId(i=841) (User(role=<UserRole.User: 3>, name=None)) ERROR:asyncua.server.uaprocessor:sending service fault response: "The server does not support the requested service." (BadServiceUnsupported) INFO:asyncua.server.uaprocessor:re-publish request (User(role=<UserRole.User: 3>, name=None)) INFO:asyncua.server.uaprocessor:re-publish request (User(role=<UserRole.User: 3>, name=None))

mikakaraila commented 3 years ago

And with Prosys UA Simulation Server node-red OPCUA client and UaExpert can re-connect:

mikakaraila commented 3 years ago

Node-red flow console shows re-connect warn messages:

mikakaraila commented 3 years ago

It is somehow related to this issue:

https://github.com/FreeOpcUa/python-opcua/issues/594

mikakaraila commented 3 years ago

Node-red client (node-opcua) fails to reconnect, server disconnects client by error:

OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! Starting Reconnection !!!!!!!!!!!!!!!!!!! 4 Jan 16:55:13 - [warn] [OpcUa-Client:b5077895.6fbab8] OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! Starting Reconnection !!!!!!!!!!!!!!!!!!! OpcUaClientNode: backoff attempt #0 retrying in 5 seconds 4 Jan 16:55:14 - [warn] [OpcUa-Client:b5077895.6fbab8] OpcUaClientNode: backoff attempt #0 retrying in 5 seconds OpcUaClientNode: backoff attempt #1 retrying in 10 seconds 4 Jan 16:55:20 - [warn] [OpcUa-Client:b5077895.6fbab8] OpcUaClientNode: backoff attempt #1 retrying in 10 seconds OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! CONNECTION RE-ESTABLISHED !!!!!!!!!!!!!!!!!!! 4 Jan 16:55:30 - [warn] [OpcUa-Client:b5077895.6fbab8] OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! CONNECTION RE-ESTABLISHED !!!!!!!!!!!!!!!!!!! OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! Starting Reconnection !!!!!!!!!!!!!!!!!!! 4 Jan 16:55:30 - [warn] [OpcUa-Client:b5077895.6fbab8] OpcUaClientNode: !!!!!!!!!!!!!!!!!!!!!!!! Starting Reconnection !!!!!!!!!!!!!!!!!!! Disconnected following reconnection failure Connection Break

EliasReuter commented 3 years ago

I tried @s4ke procedure to test it but with UaAnsiCServer OPC UA Test Server and following error appeared:

mikakaraila commented 3 years ago

Did you check opc-ua-server.py, it needs to modify if you use Python version > 3.6

Server code seems to miss modify subscription and thus cannot response to client request to change subscription to new session... problem is located to server and node-opcua library that handles error response to modify subscription.

UaExpert seems to delete subscription and create a new one as node-opcua stops it to "BadServiceUnsupported". I will ask Etienne to check this, but it can take longer time as with commercial servers re-connect is working correctly.

mikakaraila commented 3 years ago

@EliasReuter can you check what happens on UaAnsiCServer server? As I have commented this case, I have been looking server console/log and node-red console. Debug tab tells only error that server returns on response and if the response does not contain any extra info then we cannot see actual error & solve this case.

Also testing this problem with UaExpert could show some extra info, can you make same testing with UaExpert with UaAnsiCServer?

mikakaraila / node-red-contrib-opcua

uncatchable error on read client #208