search

BiancoRoyal / node-red-contrib-iiot-opcua

deprecated - very new developed by PLUS for Node-RED - https://plus4nodered.com
https://www.npmjs.com/package/node-red-contrib-iiot-opcua
BSD 3-Clause "New" or "Revised" License
34 stars 9 forks source link

Failure when using OPCUA-Server open62541 #26

Closed w4tsn closed 6 years ago

w4tsn commented 6 years ago

When trying to use the examples/read.json with a locally running open62541 OPC-UA server I encounter several problems.

I started with the example server and client and just had to change the following to make it work:

  1. on the server enable anonymous access
  2. on the client allow non-existing endpoint

After that worked and a connection was established I changed the URL from opc.tcp://localhost:55388/ to opc.tcp://localhost:16664/, which results in the following errors:

  1. Read-Node: Error: Session Not Valid On Read
  2. Read-Node: Error: ServiceResult is BadIdentityTokenInvalid (0x80200000)
  3. Connector-Node: Error stopping node: TimeoutError: timed out after 15000ms

The Server-Log says:

[03/09/2018 23:26:21.106] info/network  Connection 12 | New connection over TCP from 127.0.0.1:33367
[03/09/2018 23:26:21.118] info/channel  Connection 12 | SecureChannel 9 | OpenSecureChannel: Opened SecureChannel
[03/09/2018 23:26:21.133] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/09/2018 23:26:22.223] info/session  Connection 0 | SecureChannel 0 | Session da6f9489-ceae-7380-2f12-2162924924c2 | ActivateSession: SecureChannel 9 wants to activate, but the UserIdentify token is invalid
[03/09/2018 23:26:41.013] info/network  Connection 13 | New connection over TCP from 127.0.0.1:33384
[03/09/2018 23:26:41.025] info/channel  Connection 13 | SecureChannel 10 | OpenSecureChannel: Opened SecureChannel
[03/09/2018 23:26:41.040] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/09/2018 23:26:42.092] info/session  Connection 0 | SecureChannel 0 | Session f112a31c-8f1a-ba90-debd-7bd714a14a64 | ActivateSession: SecureChannel 10 wants to activate, but the UserIdentify token is invalid

Versions

OPC related node packages:

"node-opcua": "^0.2.2",
"node-red-contrib-iiot-opcua": "^2.1.1"

open62541 in version 0.2

Node 8.9.4 NPM 5.6.0 Node-RED 0.17.5

Related Issues

This issue from node-opcua might be related: https://github.com/node-opcua/node-opcua/issues/452

biancode commented 6 years ago

please test again with v2.2.0

w4tsn commented 6 years ago

Tested with v2.2.1

With checked fields for Endpoint Must Exist and Auto Select Endpoint.

Unchecking Endpoint Must Exist results in the error Connector-Node: Error stopping node: TimeoutError: timed out after 15000ms

Now the read node states connected though it throws one "Error: Session Not Ready To Read" before that. Invoking a read for the node current.time results in the same error message, though the read node states connected. The read node takes some time to connect. About 1 - 2 minutes.

Error log of server is now

Note that after the read node states connected the server reports Session has timed out instead of "user token invalid".

Also after waiting for about 5 minutes and after the read node states connected the server prints [03/11/2018 21:31:40.899] info/channel Connection 21 | SecureChannel 18 | Service request 473 without a valid session.

[03/11/2018 21:05:45.655] info/network  TCP network layer listening on opc.tcp://othermo-g0002.gateways.othermo.de:16664
[03/11/2018 21:06:00.105] info/network  Connection 4 | New connection over TCP from 127.0.0.1:35856
[03/11/2018 21:06:00.325] info/channel  Connection 4 | SecureChannel 1 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:06:00.651] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:06:12.477] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:06:12.516] info/channel  Connection 4 | SecureChannel 1 | CloseSecureChannel
[03/11/2018 21:07:12.570] info/network  Connection 5 | New connection over TCP from 127.0.0.1:35874
[03/11/2018 21:07:12.583] info/channel  Connection 5 | SecureChannel 2 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:07:12.593] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:07:12.630] info/session  Connection 0 | SecureChannel 0 | Session ddac81cb-e374-4dc7-7117-9139ad7a57e5 | ActivateSession: SecureChannel 2 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:07:53.892] info/session  Connection 0 | SecureChannel 0 | Session ddac81cb-e374-4dc7-7117-9139ad7a57e5 | Calling service 473 on a non-activated session
[03/11/2018 21:07:54.290] info/channel  Connection 5 | SecureChannel 2 | CloseSecureChannel
[03/11/2018 21:08:10.959] info/network  Connection 6 | New connection over TCP from 127.0.0.1:35881
[03/11/2018 21:08:10.982] info/channel  Connection 6 | SecureChannel 3 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:08:10.997] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:08:11.018] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:08:11.035] info/channel  Connection 6 | SecureChannel 3 | CloseSecureChannel
[03/11/2018 21:09:11.059] info/network  Connection 7 | New connection over TCP from 127.0.0.1:35888
[03/11/2018 21:09:11.075] info/channel  Connection 7 | SecureChannel 4 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:09:11.085] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:09:11.117] info/session  Connection 0 | SecureChannel 0 | Session ad65aa16-effd-9925-5e85-a8daabca5c35 | ActivateSession: SecureChannel 4 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:09:55.010] info/network  Connection 8 | New connection over TCP from 127.0.0.1:35893
[03/11/2018 21:09:55.023] info/channel  Connection 8 | SecureChannel 5 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:09:55.038] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:09:55.046] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:09:55.053] info/channel  Connection 8 | SecureChannel 5 | CloseSecureChannel
[03/11/2018 21:10:15.639] info/session  Connection 0 | SecureChannel 0 | Session ad65aa16-effd-9925-5e85-a8daabca5c35 | Session has timed out
[03/11/2018 21:10:55.071] info/network  Connection 9 | New connection over TCP from 127.0.0.1:35900
[03/11/2018 21:10:55.085] info/channel  Connection 9 | SecureChannel 6 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:10:55.101] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:10:55.143] info/session  Connection 0 | SecureChannel 0 | Session fc55010b-b12b-d5b7-0ad0-3d73b7dbfd1f | ActivateSession: SecureChannel 6 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:11:00.268] info/session  Connection 0 | SecureChannel 0 | Session fc55010b-b12b-d5b7-0ad0-3d73b7dbfd1f | Calling service 473 on a non-activated session
[03/11/2018 21:11:00.273] info/channel  Connection 9 | SecureChannel 6 | CloseSecureChannel
[03/11/2018 21:11:17.319] info/network  Connection 10 | New connection over TCP from 127.0.0.1:35903
[03/11/2018 21:11:17.332] info/channel  Connection 10 | SecureChannel 7 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:11:17.348] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:11:17.356] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:11:17.363] info/channel  Connection 10 | SecureChannel 7 | CloseSecureChannel
[03/11/2018 21:11:45.698] info/network  Connection 11 | New connection over TCP from 127.0.0.1:35908
[03/11/2018 21:11:45.710] info/channel  Connection 11 | SecureChannel 8 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:11:45.726] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:11:45.735] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:11:45.742] info/channel  Connection 11 | SecureChannel 8 | CloseSecureChannel
[03/11/2018 21:12:17.381] info/network  Connection 12 | New connection over TCP from 127.0.0.1:35911
[03/11/2018 21:12:17.394] info/channel  Connection 12 | SecureChannel 9 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:12:17.423] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:12:17.462] info/session  Connection 0 | SecureChannel 0 | Session 0d9a1eea-a241-e59d-3153-65768cb8cb9c | ActivateSession: SecureChannel 9 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:12:45.758] info/network  Connection 13 | New connection over TCP from 127.0.0.1:35916
[03/11/2018 21:12:45.772] info/channel  Connection 13 | SecureChannel 10 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:12:45.793] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:12:45.822] info/session  Connection 0 | SecureChannel 0 | Session e168c25a-5550-6e31-4af4-4f1417413403 | ActivateSession: SecureChannel 10 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:13:25.637] info/session  Connection 0 | SecureChannel 0 | Session 0d9a1eea-a241-e59d-3153-65768cb8cb9c | Session has timed out
[03/11/2018 21:13:55.636] info/session  Connection 0 | SecureChannel 0 | Session e168c25a-5550-6e31-4af4-4f1417413403 | Session has timed out
[03/11/2018 21:18:02.976] info/session  Try to use Session with token ecc21863-61f1-e5d1-d61d-0190d37d6746 but is not found
[03/11/2018 21:18:02.976] info/channel  Connection 13 | SecureChannel 10 | Service request 473 without a valid session
[03/11/2018 21:18:02.982] info/channel  Connection 13 | SecureChannel 10 | CloseSecureChannel
[03/11/2018 21:18:20.024] info/network  Connection 14 | New connection over TCP from 127.0.0.1:35949
[03/11/2018 21:18:20.037] info/channel  Connection 14 | SecureChannel 11 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:18:20.053] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:18:20.061] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:18:20.067] info/channel  Connection 14 | SecureChannel 11 | CloseSecureChannel
[03/11/2018 21:18:30.659] info/network  Connection 15 | New connection over TCP from 127.0.0.1:35951
[03/11/2018 21:18:30.666] info/channel  Connection 15 | SecureChannel 12 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:18:30.674] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:18:30.682] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:18:30.689] info/channel  Connection 15 | SecureChannel 12 | CloseSecureChannel
[03/11/2018 21:19:20.085] info/network  Connection 16 | New connection over TCP from 127.0.0.1:35958
[03/11/2018 21:19:20.098] info/channel  Connection 16 | SecureChannel 13 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:19:20.106] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:19:20.136] info/session  Connection 0 | SecureChannel 0 | Session 8157080c-fbff-3bf6-32b3-ab9a68862802 | ActivateSession: SecureChannel 13 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:19:30.706] info/network  Connection 17 | New connection over TCP from 127.0.0.1:35961
[03/11/2018 21:19:30.718] info/channel  Connection 17 | SecureChannel 14 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:19:30.732] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:19:30.757] info/session  Connection 0 | SecureChannel 0 | Session 13ea9a9f-566b-2132-d41d-d1cdf46fd6ad | ActivateSession: SecureChannel 14 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:20:25.631] info/session  Connection 0 | SecureChannel 0 | Session 8157080c-fbff-3bf6-32b3-ab9a68862802 | Session has timed out
[03/11/2018 21:20:35.631] info/session  Connection 0 | SecureChannel 0 | Session 13ea9a9f-566b-2132-d41d-d1cdf46fd6ad | Session has timed out
[03/11/2018 21:26:13.161] info/session  Try to use Session with token 24c68fab-43a3-4747-5ee5-fe1fa20ac0dc but is not found
[03/11/2018 21:26:13.161] info/channel  Connection 17 | SecureChannel 14 | Service request 473 without a valid session
[03/11/2018 21:26:13.166] info/channel  Connection 17 | SecureChannel 14 | CloseSecureChannel
[03/11/2018 21:26:30.206] info/network  Connection 18 | New connection over TCP from 127.0.0.1:36002
[03/11/2018 21:26:30.217] info/channel  Connection 18 | SecureChannel 15 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:26:30.231] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:26:30.244] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:26:30.250] info/channel  Connection 18 | SecureChannel 15 | CloseSecureChannel
[03/11/2018 21:26:55.838] info/network  Connection 19 | New connection over TCP from 127.0.0.1:36005
[03/11/2018 21:26:55.850] info/channel  Connection 19 | SecureChannel 16 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:26:55.865] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:26:55.880] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:26:55.894] info/channel  Connection 19 | SecureChannel 16 | CloseSecureChannel
[03/11/2018 21:27:30.267] info/network  Connection 20 | New connection over TCP from 127.0.0.1:36010
[03/11/2018 21:27:30.280] info/channel  Connection 20 | SecureChannel 17 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:27:30.295] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:27:30.324] info/session  Connection 0 | SecureChannel 0 | Session dcb87db1-304a-852a-5365-6696db7de71e | ActivateSession: SecureChannel 17 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:27:55.908] info/network  Connection 21 | New connection over TCP from 127.0.0.1:36013
[03/11/2018 21:27:55.920] info/channel  Connection 21 | SecureChannel 18 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:27:55.933] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:27:55.965] info/session  Connection 0 | SecureChannel 0 | Session ac3af23d-fc06-883e-fd3f-8348ea2ec22c | ActivateSession: SecureChannel 18 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:28:35.624] info/session  Connection 0 | SecureChannel 0 | Session dcb87db1-304a-852a-5365-6696db7de71e | Session has timed out
[03/11/2018 21:29:05.624] info/session  Connection 0 | SecureChannel 0 | Session ac3af23d-fc06-883e-fd3f-8348ea2ec22c | Session has timed out
[03/11/2018 21:31:40.899] info/session  Try to use Session with token 6f57cc35-bfda-49fe-abaa-6a0680484494 but is not found
[03/11/2018 21:31:40.899] info/channel  Connection 21 | SecureChannel 18 | Service request 473 without a valid session
[03/11/2018 21:31:40.906] info/channel  Connection 21 | SecureChannel 18 | CloseSecureChannel
[03/11/2018 21:31:57.947] info/network  Connection 22 | New connection over TCP from 127.0.0.1:36037
[03/11/2018 21:31:57.960] info/channel  Connection 22 | SecureChannel 19 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:31:57.974] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:31:57.985] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:31:57.991] info/channel  Connection 22 | SecureChannel 19 | CloseSecureChannel
[03/11/2018 21:32:58.007] info/network  Connection 23 | New connection over TCP from 127.0.0.1:36043
[03/11/2018 21:32:58.019] info/channel  Connection 23 | SecureChannel 20 | OpenSecureChannel: Opened SecureChannel
[03/11/2018 21:32:58.033] info/session  Try to use Session with token 00000000-0000-0000-0000-000000000000 but is not found
[03/11/2018 21:32:58.085] info/session  Connection 0 | SecureChannel 0 | Session 37fcf23c-fc80-5e50-1ad1-8d385825f20f | ActivateSession: SecureChannel 20 wants to activate, but the UserIdentify token is invalid
[03/11/2018 21:34:05.620] info/session  Connection 0 | SecureChannel 0 | Session 37fcf23c-fc80-5e50-1ad1-8d385825f20f | Session has timed out
w4tsn commented 6 years ago

Like suggested in #29 I setup a complete new flow with a new connector and read/inject nodes. Still the same issue. The read node states connected or even active (one time, could not reproduce).

Does someone have any idea where to look next? Do you think it is a iiot-opcua error, a node-opcua client error, a open62541 server error or something in combination between the two/three? I'm a bit puzzled right now with this :S

biancode commented 6 years ago

I'll test it with open62541. Best for that is if you could give me a setup tutorial to get the same environment for tests.

biancode commented 6 years ago

@erossignon did you get some questions or experinces in that topic?

biancode commented 6 years ago

@w4tsn if you test it with the opcua-commander and it works, then it is my problem here. The connector is like the commander.

w4tsn commented 6 years ago

Test-Env

@biancode my co-worker

  1. downloaded the release 0.2 package for raspberrypi,
  2. unzipped it
  3. and started the plain example server without modifications

I replicated this setup on my linux 64 machine with the corresponding release package and it worked out of the box.

Further tests

I tested to connect to open62541 with python3 opcu-client and opcua-commander.

With opcua-client I tested a locally running server on linux 64 as well as the ssh-piped server from the remote raspberrypi, which both worked. On the remote machine I installed opcua-commander and tried to connect to the local server but failed. The program exited right after start with the same server log messages as stated above like timeout.

w4tsn commented 6 years ago

So, if this is an issue with the opcua-commander, I'll open an issue for connection to open62541 there. What do you think @biancode?

biancode commented 6 years ago

Yes, please. It could be placed as a node-opcua issue too.

Sent with GitHawk

biancode commented 6 years ago

open62541 problem

w4tsn commented 6 years ago

Seems to be fixed in master of open62541. Should work in 0.3-rc2.