Log In
Register
Forum
Topic RSS
11:27, EEST
August 22, 2019
Offline
The client connects to the server with username/password. Security mode and security policy are set to None.
Every 30 seconds, the client calls a method on the server. After several days of normal operation, the call fails with Bad_SecureChannelIdInvalid. The client then logs this error on every call to the server for the next 21 hours, until it gets an “Unidentified message” from the server and loses the connection.
Client and server are running on the same machine (Asus tinkerboard), so communication should not be an issue.
Client and server are both using prosys-opc-ua-sdk-client-server-4.0.0-774.jar
Client log extract:
.
. (Normal operation, no errors or warning)
.
12:00:38.677 [TcpConnection/Read] WARN c.p.u.s.t.t.i.TcpConnection – localhost/127.0.0.1:4840 Error
com.prosysopc.ua.stack.common.ServiceResultException: Bad_SecureChannelIdInvalid (code=0x80220000, description=”Bad_SecureChannelIdInvalid (code=0x80220000, description=”The specified secure channel is no longer valid.”)”)
at com.prosysopc.ua.stack.transport.tcp.io.TcpConnection$b.run(SourceFile:276)
12:00:39.515 [http-nio-80-exec-9] ERROR n.e.a.w.b.ErrorBean – Encountered error in hmi core handler.
.
. ( Internal stack trace omitted)
.
Caused by: com.prosysopc.ua.ServiceException: Bad_SecureChannelIdInvalid (code=0x80220000, description=”Bad_SecureChannelIdInvalid (code=0x80220000, description=”The specified secure channel is no longer valid.”)”)
at com.prosysopc.ua.client.UaClient.a(SourceFile:5345)
at com.prosysopc.ua.client.UaClient.read(SourceFile:2830)
at com.prosysopc.ua.client.UaClient.readAttributes(SourceFile:3112)
at com.prosysopc.ua.client.UaClient.readAttributes(SourceFile:3079)
at com.prosysopc.ua.client.AddressSpace.getNode(SourceFile:897)
at com.prosysopc.ua.client.AddressSpace.getMethod(SourceFile:749)
at no.triona.opc.client.util.MethodCaller.getMethod(MethodCaller.java:36)
… 21 common frames omitted
Caused by: com.prosysopc.ua.stack.common.ServiceResultException: Bad_SecureChannelIdInvalid (code=0x80220000, description=”Bad_SecureChannelIdInvalid (code=0x80220000, description=”The specified secure channel is no longer valid.”)”)
at com.prosysopc.ua.stack.transport.tcp.io.TcpConnection$b.run(SourceFile:276)
.
. (Same warnings and errors repeated with (approx) 30 sec. intervals
.
06:52:02.803 [TcpConnection/Read] WARN c.p.u.s.t.t.i.SecureChannelTcp – 4 Unidentified message, RequestId=266467, type=ReadResponse!
.
. After this the client loses the connection to the server.
.
On the server side, we do not get any error or warning messages, until:
06:52:19.147 [OPC-UA-Stack-Blocking-Work-Executor-4] WARN c.p.u.s.NodeManagementServiceHandler – validateRequest: Request=CallRequest serverSecureChannel=SecureChannelId=5 State=Open URL=opc.tcp://tinkerboard:4840/OPCUA/SMServer SecurityPolicy=http://opcfoundation.org/UA/SecurityPolicy#None RemoteAddress=/127.0.0.1:47412 session.SecureChannelId=SecureChannelId=4 State=Closed URL=opc.tcp://tinkerboard:4840/OPCUA/SMServer SecurityPolicy=http://opcfoundation.org/UA/SecurityPolicy#None RemoteAddress=null session=99f6d3a2-e868-4912-8c52-d0c8fdcce346-00A9EB1E (ID=ns=1;g=552d83be-2c95-435b-a196-fefdd82153a2 Token=b=E7QoRLGtw3LT/hzVmFgC5l8LA2eIgA0Lk5fF7gvMeWo= Channel=(SecureChannelId=4 State=Closed URL=opc.tcp://tinkerboard:4840/OPCUA/SMServer SecurityPolicy=http://opcfoundation.org/UA/SecurityPolicy#None RemoteAddress=null))
13:03, EEST
April 3, 2012
Offline
Hi,
Hmm seems weird. I’m going to assume you have not modified any defaults on the UaClient e.g. for statuscheck intervals or anything other that might relate to this and additionally that the clock on the board works correctly.
The secure channel is periodically renewed, by default when it is 75% old and the default lifetime is 1 hour. In some cases when using e.g. hibernation on a laptop, the error message (Bad_SecureChannelIdInvalid) might be seen (typically only once), after which UaClient would automatically reconnect.
Could it be possible to get the logs (for both the client and the server side)? If yes, please send them to uajava-support@prosysopc.com.
What OS and java version/vendor you use on the board?
If this were to happen again, the DEBUG level of the logs could indicate something, however do note that on the DEBUG level it will output a lot.
14:38, EEST
August 22, 2019
Offline
The logging level was set to WARN, so the log messages included in the original post is pretty much all there is.
As mentioned in the original post, the setup ran without problems for several days, so it may be difficult to use full DEBUG log.
Can I tune logback.xml to only use DEBUG on the relevant parts in the stack?
The Java and OS version we are using is:
Java version:
/usr/lib/jvm/java-8-openjdk-armhf/jre/bin/java -version
Picked up JAVA_TOOL_OPTIONS: -Dgnu.io.rxtx.SerialPorts=/dev/tty96B0
openjdk version “1.8.0_212”
OpenJDK Runtime Environment (build 1.8.0_212-8u212-b01-1~deb9u1-b01)
OpenJDK Client VM (build 25.212-b01, mixed mode)
——————–
OS version:
cat /etc/os-release
PRETTY_NAME=”Debian GNU/Linux 9 (stretch)”
NAME=”Debian GNU/Linux”
VERSION_ID=”9″
VERSION=”9 (stretch)”
ID=debian
HOME_URL=”https://www.debian.org/”
SUPPORT_URL=”https://www.debian.org/support”
BUG_REPORT_URL=”https://bugs.debian.org/”
hostnamectl
Static hostname: tinkerboard
Icon name: computer
Machine ID: e365fafe80814192ad32cabce20416c8
Boot ID: 78a7cc4e81d24981b188fda0a3ce7aa3
Operating System: Debian GNU/Linux 9 (stretch)
Kernel: Linux 4.4.103+
Architecture: arm
16:01, EEST
April 3, 2012
Offline
First would be best to check if you have a line “Failed to renew security token.” in the (client) logs. This would be logged by SecureChannelTcp (and the line prefixed with the id from the channel and following the exception stacktrace). And if yes, does the server logs have something at the same time.
To some extent you could try DEBUG only for some classes, however assuming it is a bug then it might be hard to locate as the stack layer has a lot of classes. Note that this could be thrown on the “SDK layer” as well (or well technically the stack layer is part of the SDK in 4.x but I hope that was clear enough). List of classes that could contribute to this (non-exhaustive):
com.prosysopc.ua.server.SessionManager
com.prosysopc.ua.server.SessionServiceHandler
These handle sessions on the server side, Bad_SecureChannelIdInvalid would be thrown by the SessionManager if the Session is tried to be activated on wrong channel id, would be logged by SessionServiceHandler.
com.prosysopc.ua.stack.transport.tcp.nio.OpcTcpServerConnection
com.prosysopc.ua.stack.transport.tcp.nio.OpcTcpServerSecureChannel
These are lower-levels for the connection on the server side and would show e.g. “SecureChannel renewed + the token” when it is renewed. Additionally they would throw the Bad_SecureChannelIdInvalid if the channel is not present and this would be sent to the client.
com.prosysopc.ua.stack.transport.tcp.io.TcpConnection
com.prosysopc.ua.stack.transport.tcp.io.SecureChannelTcp
These are lower-levels for the connection on the client side and would show e.g. “createSecureChannel: renew=true/false” when the channel is formed or renewed.
Even those 6, it will output quite a lot of logs.
17:39, EEST
August 22, 2019
Offline
I cannot see any “Failed to renew security token.” message in the logs before the first Bad_SecureChannelIdInvalid occurred.
After the client lost the connection (at 06:52:02.803 in the log snippet in my first post) it keeps on logging that it has lost connection to the OPC-UA server
Caused by: com.prosysopc.ua.client.ServerConnectionException: Server not connected: opc.tcp://localhost:4840/OPCUA/SMServer [http://opcfoundation.org/UA/SecurityPolicy#None,None]
at com.prosysopc.ua.client.UaClient.G(SourceFile:6285)
at com.prosysopc.ua.client.UaClient.a(SourceFile:5337)
at com.prosysopc.ua.client.UaClient.read(SourceFile:2830)
at com.prosysopc.ua.client.UaClient.readAttributes(SourceFile:3112)
at com.prosysopc.ua.client.UaClient.readAttributes(SourceFile:3079)
at com.prosysopc.ua.client.AddressSpace.readAttributes(SourceFile:1435)
at com.prosysopc.ua.client.AddressSpace.readNode(SourceFile:1489)
at com.prosysopc.ua.client.AddressSpace.getNode(SourceFile:926)
at com.prosysopc.ua.client.AddressSpace.getMethod(SourceFile:749)
It keeps on logging this for a while (25 minutes) until the log stops.
I can find the “Failed to renew” message in the logs, but the only occurrence of this message is 2 days AFTER the first Bad_SecureChannelIdInvalid message
22:58:03.188 [TcpConnection/Read] WARN c.p.u.s.t.t.i.TcpConnection – localhost/127.0.0.1:4840 Sequence number mismatch: 136479 vs. 136481
22:58:05.040 [OPC-UA-Stack-Blocking-Work-Executor-32] WARN c.p.u.c.UaClient$a – onError:
com.prosysopc.ua.stack.common.ServiceResultException: Bad_UnexpectedError (code=0x80010000, description=”Sequence number mismatch”)
at com.prosysopc.ua.stack.transport.tcp.io.TcpConnection$b.run(SourceFile:393)
22:58:05.040 [OPC-UA-Stack-Blocking-Work-Executor-11] ERROR c.p.u.s.t.t.i.SecureChannelTcp – 12 Failed to renew security token.
com.prosysopc.ua.stack.common.ServiceResultException: Bad_UnexpectedError (code=0x80010000, description=”Sequence number mismatch”)
at com.prosysopc.ua.stack.transport.tcp.io.TcpConnection$b.run(SourceFile:393)
22:58:03.200 [HMIPoller] WARN c.p.u.c.n.UaClientReference – Unable to retrieve node from AddressSpace:
com.prosysopc.ua.ServiceException: Bad_UnexpectedError (code=0x80010000, description=”Sequence number mismatch”)
at com.prosysopc.ua.client.AddressSpace.browse(SourceFile:381)
at com.prosysopc.ua.client.AddressSpace.browse(SourceFile:2046)
at com.prosysopc.ua.client.AddressSpace.browse(SourceFile:348)
at com.prosysopc.ua.client.AddressSpace.readReferences(SourceFile:1543)
at com.prosysopc.ua.client.AddressSpace.getNode(SourceFile:930)
at com.prosysopc.ua.client.nodes.UaClientReference.a(SourceFile:257)
at com.prosysopc.ua.client.nodes.UaClientReference.a(SourceFile:244)
at com.prosysopc.ua.client.nodes.UaClientReference.getTargetNode(SourceFile:193)
at com.prosysopc.ua.client.nodes.UaNodeImpl.beforeAddReference(SourceFile:810)
at com.prosysopc.ua.client.nodes.UaNodeImpl.addReference(SourceFile:760)
at com.prosysopc.ua.client.nodes.UaNodeImpl.addReference(SourceFile:151)
at com.prosysopc.ua.client.AddressSpace.readReferences(SourceFile:1562)
at com.prosysopc.ua.client.AddressSpace.getNode(SourceFile:930)
at com.prosysopc.ua.client.AddressSpace.getMethod(SourceFile:749)
14:45, EEST
August 22, 2019
Offline
A related question:
Why do we get Bad_SecureChannelIdInvalid and “Failed to renew security token.” when security mode and security policy are set to None?
15:31, EEST
April 3, 2012
Offline
The “channel” on which the messages are being sent is called “SecureChannel” in the specification. Most of the rules apply regardless if security is used or not. One way to think about is that not using security is a special exception to a system of rules that is written for security in mind. The error code names are also defined in the specification and the lifetime of the channel is defined as a lifetime of a “SecurityToken”.
Most Users Ever Online: 1919
Currently Online:
16 Guest(s)
Currently Browsing this Page:
1 Guest(s)
Top Posters:
Heikki Tahvanainen: 402
hbrackel: 144
rocket science: 88
pramanj: 86
Francesco Zambon: 83
Ibrahim: 78
Sabari: 62
kapsl: 57
gjevremovic: 49
Xavier: 43
Member Stats:
Guest Posters: 0
Members: 736
Moderators: 7
Admins: 1
Forum Stats:
Groups: 3
Forums: 15
Topics: 1524
Posts: 6450
Newest Members:
kristiewinkle8, rust, christamcdowall, redaahern07571, nigelbdhmp, travistimmons, AnnelCib, dalenegettinger, howardkennerley, ThomassnismModerators: Jouni Aro: 1026, Pyry: 1, Petri: 0, Bjarne Boström: 1026, Jimmy Ni: 26, Matti Siponen: 346, Lusetti: 0
Administrators: admin: 1
