Log In
Register
Forum
Topic RSS
18:29, EET
March 11, 2020
Offline
I’m trying to reproduce a problem reported by a customer.
Logs generated by server in the problem scenario:
INFO [07:43:06 24-Feb-20 PST][opcUaServer.certificateValidationListener] * The Certificate is self-signed.
FINE [07:43:06 24-Feb-20 PST][opcUaServer.server] onCreateSession urn:alawrence10-lt:UnifiedAutomation:UaExpert
INFO [07:43:06 24-Feb-20 PST][opcUaServer.userValidator] onValidate: userIdentity.type = UserName
FINE [07:43:16 24-Feb-20 PST][opcUaServer.server] onCloseSession urn:alawrence10-lt:UnifiedAutomation:UaExpert false
Logs generated in my attempt to reproduce it, when I connect, and then disconnect:
INFO [11:34:57 11-Mar-20 EDT][opcUaServer.certificateValidationListener] * The Certificate is self-signed.
FINE [11:34:57 11-Mar-20 EDT][opcUaServer.server] onCreateSession urn:alawrence10-lt:UnifiedAutomation:UaExpert
INFO [11:35:00 11-Mar-20 EDT][opcUaServer.userValidator] onValidate: userIdentity.type = UserName
FINE [11:35:00 11-Mar-20 EDT][opcUaServer.server] onActivateSession urn:alawrence10-lt:UnifiedAutomation:UaExpert opc1
FINE [11:35:00 11-Mar-20 EDT][opcUaServer.server] onAfterActivateSession urn:alawrence10-lt:UnifiedAutomation:UaExpert
FINE [11:35:17 11-Mar-20 EDT][opcUaServer.server] onCloseSession urn:alawrence10-lt:UnifiedAutomation:UaExpert true
It looks like, in the problem scenario the server, instead of calling onActivateSession, just waits ten seconds and then calls com.prosysopc.ua.server.SessionManagerListener.onCloseSession(Session session, false)
Is there anything helpful that can be deduced from that? Reportedly, it just happens on one particular machine, and only when using UserName, not Anonymous. Apparently it also happened last July, and it was also particular to one machine, or machines with certain IT policies in place. This was the server log in that case:
SCHWERWIEGEND [16:45:57 26-Jul-19 MESZ][opcUaClient.client] OpcUaDevice.ping(): exception: Failed to activate Session.
With SecurityMode Sign Ecript Basic256 Sha256
FEIN [16:50:57 26-Jul-19 MESZ][opcUaServer.server] onCreateSession NiagaraOpcUaClient
INFORMATION [16:50:57 26-Jul-19 MESZ][opcUaServer.userValidator] onValidate: userIdentity.type = UserName
FEIN [16:51:07 26-Jul-19 MESZ][opcUaServer.server] onCloseSession NiagaraOpcUaClient false
SCHWERWIEGEND [16:51:15 26-Jul-19 MESZ][opcUaClient.client] OpcUaDevice.ping(): exception: Failed to activate Session.
13:55, EET
April 3, 2012
Offline
Hi,
I guess first I need to ask that what versions of the SDK was used to make the server? Additionally where possible, what versions of UaExpert were used in both cases?
As of OPC UA 1.04, there are checks that should be done after CreateSessionResponse is received from the server. Depending on versions either side might have bugs or incorrect impls. For example, at least the very old SDK 1.x server doesn’t return EndpointDescriptions exactly as it should, thus might fail vs. some modern checks. Some versions of some clients might fail the session creation rigth there, others might have a “try anyway” option. Thus it is important to know what versions were used.
20:13, EET
March 11, 2020
Offline
ProSys 2.2.J633-721 is the SDK used for the server. And UaExpert “1.5.1 331” is the client I used in my attempt to reproduce. My customer reports that he encountered the problem with both the UaExpert “1.5.1 331” client, and also prosys-opc-ua-browser-windows-x64-4.0.2-231.
10:37, EET
April 3, 2012
Offline
Thanks. It should be noted that in general that version of the SDK is quite old. While this issue doesn’t ring any bells immediately, we have fixed quite a lot since that version (and that build is pretty much same as 2.3.0 other than one publishrequest fix): https://www.prosysopc.com/products/opc-ua-java-sdk/release-history/version2.html, https://downloads.prosysopc.com/opcua/Prosys_OPC_UA_Java_SDK_3_Release_Notes.html, https://downloads.prosysopc.com/opcua/Prosys_OPC_UA_SDK_for_Java_4_Release_Notes.html.
At least on my machine it works with that SDK version + UaExpert + UA Browser (tested vs. the sampleconsoleserver), but I guess that is somewhat expected result since this was happening in just one machine. However I didn’t yet test Basic256Sha256 specifically, since by default that is not enabled in that old version samples (I do not remember exactly why, but at least when it initially was specified I think we defaulted still 1k certs whereas that policy needs a 2k cert at minimum, but the sample does make a 2k cert so not sure..).
Also, just as clarfication, is this “one particular machine” the client or the server? (I’m assuming the server, but just to be sure). Also does it break randomly or every time, i.e. how reproducable this is? Is there any JVM version differences between a working machine and failing one?
Since it happens also with the UA Browser, your customer could check does (user.home)\.prosysopc\prosys-opc-ua-browser\log give any indication what goes wrong? Or does the “Log” view in UaExpert give any errors?
22:26, EET
March 11, 2020
Offline
The following is from my customer:
I first initiated an anonymous connection at 11:32, which connected successfully, and then disconnected at 11:33.
At 11:36 I initiated a user/password authentication connection. This produced an error:
03/16/2020 11:36:37.006 INFO [JavaFX Application Thread] com.prosysopc.ua.app.uabrowser.singleclient.j [] – Normal connection mode
03/16/2020 11:36:37.007 INFO [Thread-12] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Connecting
03/16/2020 11:36:37.010 INFO [Thread-12] com.prosysopc.ua.stack.transport.tcp.io.d [] – Connected (non-reverse), handshake completed, local=/169.254.89.216:55464, remote=BMS/169.254.89.216:52520
03/16/2020 11:36:37.016 INFO [Thread-12] com.prosysopc.ua.stack.transport.tcp.io.b [] – 10 Closed
03/16/2020 11:36:37.016 INFO [TcpConnection/Read] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed (graceful)
03/16/2020 11:36:37.016 INFO [Thread-12] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed
03/16/2020 11:36:37.018 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Connecting
03/16/2020 11:36:37.020 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – Connected (non-reverse), handshake completed, local=/169.254.89.216:55465, remote=BMS/169.254.89.216:52520
03/16/2020 11:36:37.026 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.b [] – 11 Closed
03/16/2020 11:36:37.026 INFO [TcpConnection/Read] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed (graceful)
03/16/2020 11:36:37.026 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed
03/16/2020 11:36:39.064 INFO [Thread-13] com.prosysopc.ua.stack.cert.e [] – Certificate ‘26740B5CE62B8835B08B5B0062985BDBF8001CEE’ added to rejected certificates.
03/16/2020 11:36:39.065 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Connecting
03/16/2020 11:36:39.067 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – Connected (non-reverse), handshake completed, local=/169.254.89.216:55472, remote=BMS/169.254.89.216:52520
03/16/2020 11:36:57.191 INFO [Thread-13] com.prosysopc.ua.client.x [] – Failed to CloseSession:
com.prosysopc.ua.stack.c.f: ServiceFault [ResponseHeader=”ResponseHeader [Timestamp=”03/16/20 18:36:57.1910000 GMT”, RequestHandle=”682″, ServiceResult=”Bad_SessionIdInvalid (0x80250000) “The session id is not valid.””, ServiceDiagnostics=”Diagnostic Info:
“, StringTable=”null”, AdditionalHeader=”null”]”]
at com.prosysopc.ua.stack.transport.tcp.io.b.a(SourceFile:880) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.transport.tcp.io.b.a(SourceFile:808) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.a.j.a(SourceFile:305) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.transport.c.a(SourceFile:514) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.o(SourceFile:5090) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.j(SourceFile:966) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.i(SourceFile:942) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.disconnect(SourceFile:926) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.connect(SourceFile:905) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.app.uabrowser.singleclient.j.di(SourceFile:930) ~[application-4.0.2-231.jar:4.0.2-231]
at java.lang.Thread.run(Thread.java:834) [?:?]
03/16/2020 11:36:57.237 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.b [] – 12 Closed
03/16/2020 11:36:57.237 INFO [Thread-13] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed
03/16/2020 11:36:57.238 INFO [TcpConnection/Read] com.prosysopc.ua.stack.transport.tcp.io.d [] – BMS/169.254.89.216:52520 Closed (expected)
03/16/2020 11:36:57.239 ERROR [JavaFX Application Thread] com.prosysopc.ua.app.uabrowser.singleclient.j [] – Could not connect the client
com.prosysopc.ua.H: Failed to activate Session.
at com.prosysopc.ua.client.x.iR(SourceFile:5043) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.connect(SourceFile:896) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.app.uabrowser.singleclient.j.di(SourceFile:930) ~[application-4.0.2-231.jar:4.0.2-231]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.prosysopc.ua.stack.c.f: ServiceFault [ResponseHeader=”ResponseHeader [Timestamp=”03/16/20 18:36:57.1890000 GMT”, RequestHandle=”0″, ServiceResult=”Bad_InternalError (0x80020000) “An internal error occurred as a result of a programming or configuration error.””, ServiceDiagnostics=”Diagnostic Info: 0 (Bad_InternalError (0x80020000) “An internal error occurred as a result of a programming or configuration error.”)
at org.opcfoundation.ua.application.ServiceHandlerComposition$1.serve(Unknown Source)
at org.opcfoundation.ua.application.ServiceHandlerComposition.serve(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerSecureChannel.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection$4.onMessageComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.fireComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.setMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder$1.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Inner Info: 1 (Bad_InternalError (0x80020000) “An internal error occurred as a result of a programming or configuration error.”)
at com.prosysopc.ua.server.Session.getSessionName(Unknown Source)
at com.tridium.opcUaServer.BOpcUaServer.onActivateSession(BOpcUaServer.java:687)
at com.prosysopc.ua.server.SessionManager.a(Unknown Source)
at com.prosysopc.ua.server.SessionManager.activateSession(Unknown Source)
at com.prosysopc.ua.server.SessionServiceHandler.onActivateSession(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.opcfoundation.ua.application.ServiceHandlerComposition$1.serve(Unknown Source)
at org.opcfoundation.ua.application.ServiceHandlerComposition.serve(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerSecureChannel.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection$4.onMessageComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.fireComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.setMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder$1.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
“, StringTable=”[ServiceFault: Bad_InternalError (0x80020000) “An internal error occurred as a result of a programming or configuration error.”
Diagnostic Info: java.lang.NullPointerException
at com.prosysopc.ua.server.Session.getSessionName(Unknown Source)
at com.tridium.opcUaServer.BOpcUaServer.onActivateSession(BOpcUaServer.java:687)
at com.prosysopc.ua.server.SessionManager.a(Unknown Source)
at com.prosysopc.ua.server.SessionManager.activateSession(Unknown Source)
at com.prosysopc.ua.server.SessionServiceHandler.onActivateSession(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.opcfoundation.ua.application.ServiceHandlerComposition$1.serve(Unknown Source)
at org.opcfoundation.ua.application.ServiceHandlerComposition.serve(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerSecureChannel.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection.handleSecureMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection$4.onMessageComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.fireComplete(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder.setMessage(Unknown Source)
at org.opcfoundation.ua.transport.tcp.nio.SecureInputMessageBuilder$1.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
, java.lang.NullPointerException]”, AdditionalHeader=”null”]”]
at com.prosysopc.ua.stack.transport.c.a.j(SourceFile:282) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.transport.tcp.io.b.a(SourceFile:869) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.transport.tcp.io.b.a(SourceFile:808) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.a.j.a(SourceFile:305) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.transport.c.a(SourceFile:464) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.stack.a.j.a(SourceFile:178) ~[application-4.0.2-231.jar:4.0.2-231]
at com.prosysopc.ua.client.x.iR(SourceFile:5035) ~[application-4.0.2-231.jar:4.0.2-231]
… 3 more
This occurred when connecting with a client running on the same host as the Niagara station. I have previously attempted this with a client on a separate machine that was virtually NAT’d through to the host and received the same error.
14:43, EET
April 3, 2012
Offline
We have tried pretty much all we can to try to reproduce this with those versions, but have not managed to do so.
It hard to say if that NPE is the actual problem or a side-effect of one.
Since the log shows:
at com.prosysopc.ua.server.Session.getSessionName(Unknown Source)
at com.tridium.opcUaServer.BOpcUaServer.onActivateSession(BOpcUaServer.java:687) <—
at com.prosysopc.ua.server.SessionManager.a(Unknown Source)
at com.prosysopc.ua.server.SessionManager.activateSession(Unknown Source)
you could maybe try to check if there is something that can influence anything.
Other than that, you could try with DEBUG or TRACE logging levels to see if the server logs anything useful. You can email them to uajava-support@prosysopc.com. Also if possible, it might be useful to know what "certain IT policies in place" actually means. Also is there any difference in the machine OS, Java version and vendor etc? Since your case is a bit special, we might continue via email if needed.
And in general, that version is really old, please test with 4.x, since if there is something related not already fixed there, the fix would be for 4.x anyway.
Also those versions of the SDK also sometimes needed the unlimited crypto strength jurisdiction policy files on oracle jre, see https://downloads.prosysopc.com/opcua/release_notes2.0.0-194.html. Maybe check that as well.
Most Users Ever Online: 518
Currently Online:
7 Guest(s)
Currently Browsing this Page:
1 Guest(s)
Top Posters:
hbrackel: 135
pramanj: 86
Francesco Zambon: 81
rocket science: 77
ibrahim: 76
Sabari: 62
kapsl: 57
gjevremovic: 49
Xavier: 43
fred: 41
Member Stats:
Guest Posters: 0
Members: 680
Moderators: 16
Admins: 1
Forum Stats:
Groups: 3
Forums: 15
Topics: 1467
Posts: 6260
Newest Members:
sagarchau, elviralangwell4, Donnavek, Eddiefauth, DonaldPooma, fidelduke938316, Jan-Pfizer, DavidROunc, fen.pang@woodside.com, aytuleModerators: Jouni Aro: 1009, Otso Palonen: 32, Tuomas Hiltunen: 5, Pyry: 1, Petri: 0, Bjarne Boström: 983, Heikki Tahvanainen: 402, Jukka Asikainen: 1, moldzh08: 0, Jimmy Ni: 26, Teppo Uimonen: 21, Markus Johansson: 42, Niklas Nurminen: 0, Matti Siponen: 321, Lusetti: 0, Ari-Pekka Soikkeli: 5
Administrators: admin: 1
