Avatar

Please consider registering
guest

sp_LogInOut Log In sp_Registration Register

Register | Lost password?
Advanced Search

— Forum Scope —




— Match —





— Forum Options —





Minimum search word length is 3 characters - maximum search word length is 84 characters

sp_Feed Topic RSS sp_TopicIcon
Client get Bad_SecureChannelIdInvalid (code=0x80220000)
August 29, 2019
11:27, EEST
Avatar
nmnemonic
Member
Members
Forum Posts: 5
Member Since:
August 22, 2019
sp_UserOfflineSmall 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))

August 29, 2019
13:03, EEST
Avatar
Bjarne Boström
Moderator
Moderators
Forum Posts: 1032
Member Since:
April 3, 2012
sp_UserOfflineSmall 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.

August 29, 2019
14:38, EEST
Avatar
nmnemonic
Member
Members
Forum Posts: 5
Member Since:
August 22, 2019
sp_UserOfflineSmall 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

August 29, 2019
16:01, EEST
Avatar
Bjarne Boström
Moderator
Moderators
Forum Posts: 1032
Member Since:
April 3, 2012
sp_UserOfflineSmall 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.

August 29, 2019
17:39, EEST
Avatar
nmnemonic
Member
Members
Forum Posts: 5
Member Since:
August 22, 2019
sp_UserOfflineSmall 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)

September 2, 2019
14:45, EEST
Avatar
nmnemonic
Member
Members
Forum Posts: 5
Member Since:
August 22, 2019
sp_UserOfflineSmall 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?

September 2, 2019
15:31, EEST
Avatar
Bjarne Boström
Moderator
Moderators
Forum Posts: 1032
Member Since:
April 3, 2012
sp_UserOfflineSmall 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”.

Forum Timezone: Europe/Helsinki

Most Users Ever Online: 1919

Currently Online:
15 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: 728

Moderators: 7

Admins: 1

Forum Stats:

Groups: 3

Forums: 15

Topics: 1529

Posts: 6471

Newest Members:

roycedelargie91, kourtneyquisenbe, ellis87832073466, zkxwilliemae, gabriellabachus, Deakin, KTP25Zof, Wojciech Kubala, efrennowell431, wilfredostuart

Moderators: Jouni Aro: 1026, Pyry: 1, Petri: 0, Bjarne Boström: 1032, Jimmy Ni: 26, Matti Siponen: 349, Lusetti: 0

Administrators: admin: 1