Log In
Register
Forum
Topic RSS
8:27, EET
March 18, 2014
Offline
We have a unit test where we spawn a server, and often when we try to connect the test client, it fails with “Failed to retrieve endpoints. The server is not available: opc.tcp://localhost:/”. We have tried to detect that the server is up with a ServerStatusListener, but since this is a client side listener, it won’t work unless the client actually successfully connects. Are there any callbacks that can be registered to know if a server is fully initialized and shutdown, or do we actually have to “sleep” to give the server time to start up?
9:26, EET
April 3, 2012
Offline
Is the test server made with our SDK, i.e. started in the same test, or is it some external server?
If it is some external server, then you need to call UaClient.connect in a loop until you succeed (Or develop some way the the server can communicate back, e.g. if you launch with with ProcessBuilder you could maybe observe the stdout of that program).
If it is made with our SDK, then simply call UaServer.start. After that call returns, it should be ready. You can call that e.g. in some ‘setUp’ methods that most of the unit testing frameworks support
9:37, EET
March 18, 2014
Offline
It’s with the SDK. And we do it as you describe – call “start”, and then proceed. But it still seems that the server some times is not available even when “start” has returned.
11:14, EET
March 18, 2014
Offline
It seems to be a timing related issue somewhere. I have enabled debug logging, and it happens a lot less frequent. Still, when it happens, I can see a subtle difference in the log:
Successful:
2015-12-16 10:22:21,907 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] onStateTransition: Closed->Opening
2015-12-16 10:22:21,909 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] addConnectionListener: listener=org.opcfoundation.ua.transport.tcp.nio.OpcTcpServer$1$1@4e31e2ba
Unsuccessful:
2015-12-16 10:51:06,346 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] onStateTransition: Closed->Closing
2015-12-16 10:51:06,347 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isRegistered()=true
2015-12-16 10:51:06,347 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isOpen()=true
2015-12-16 10:51:06,347 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] closed
2015-12-16 10:51:06,347 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: ownsSelector=false
2015-12-16 10:51:06,348 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isRegistered()=false
2015-12-16 10:51:06,348 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isOpen()=false
2015-12-16 10:51:06,348 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: ownsSelector=false
2015-12-16 10:51:06,348 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] onStateTransition: Closing->Closed
2015-12-16 10:51:06,348 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] onStateTransition: Closed->Opening
2015-12-16 10:51:06,349 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] addConnectionListener: listener=org.opcfoundation.ua.transport.tcp.nio.OpcTcpServer$1$1@1e73179a
All output before this is otherwise similar. So in the successful case, it transitions from Closed to Opening, but in the unsuccessful case, it goes from Closed to Closing (which seems to be a different thread) before it later goes from Closed to Opening, but by then the client is already failing with “Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)”
8:54, EET
March 18, 2014
Offline
Can anyone please confirm if this is a bug or expected behaviour?
10:48, EET
April 3, 2012
Offline
So far I have been unsuccessful to reproduce this problem.
I made a small JUnit4 test which run for 1000 times and it did work.
private static AtomicInteger count = new AtomicInteger(0);
private UaClient client;
private UaServer server;
@Rule
public RepeatRule repeatRule = new RepeatRule(); //based on https://gist.github.com/fappel/8bcb2aea4b39ff9cfb6e
@Before
public void setUp() throws Exception {
String applicationName = "Test";
PkiFileBasedCertificateValidator validator = new PkiFileBasedCertificateValidator();
ApplicationDescription appDescription = new ApplicationDescription();
appDescription.setApplicationName(new LocalizedText(applicationName + "@localhost"));
appDescription.setApplicationUri("urn:localhost:OPCUA:" + applicationName);
appDescription.setProductUri("urn:prosysopc.com:OPCUA:" + applicationName);
appDescription.setApplicationType(ApplicationType.ClientAndServer);
File privatePath = new File(validator.getBaseDir(), "private");
int[] keySizes = null;
final ApplicationIdentity identity = ApplicationIdentity.loadOrCreateCertificate(
appDescription,
"Sample Organisation",
/* Private Key Password */"",
/* Key File Path */privatePath,
/* Issuer Certificate & Private Key */null,
/* Key Sizes for instance certificates to create */keySizes,
/* Enable renewing the certificate */true);
server = new UaServer();
server.setCertificateValidator(validator);
server.setApplicationIdentity(identity);
server.setPort(Protocol.OpcTcp, 55555);
server.setServerName("OPCUA/" + applicationName);
server.setBindAddresses(EndpointUtil.getInetAddresses(server.isEnableIPv6()));
server.addUserTokenPolicy(UserTokenPolicy.ANONYMOUS);
client = new UaClient("opc.tcp://localhost:55555/OPCUA/Test");
client.setCertificateValidator(validator);
client.setApplicationIdentity(identity);
client.setSecurityMode(SecurityMode.NONE);
server.start();
client.connect();
}
@After
public void tearDown() throws Exception {
client.disconnect();
server.shutdown(0, "ShutdownMessage");
}
@Test
@Repeat(times = 1000) //repeat this test X times (including @Before and @After), based on https://gist.github.com/fappel/8bcb2aea4b39ff9cfb6e
public void test() throws ServiceException, StatusException {
client.readValue(Identifiers.Server_ServerStatus); //throws exception if error
System.out.println("Iteration: "+count.incrementAndGet());
}
}
Hmm.. are you by any change trying to run the tests in parallel? Because you can only start one server per port, others would fail to start because the port is already bound.
– Bjarne
13:48, EET
March 18, 2014
Offline
No, we’re not running in parallel. However, we have a slightly different initialization procedure, as we’re creating a new namespace and adding some custom nodes and history manager. Aparently that requires us to invoke `server.init()` before `server.start()`. I’m not sure that has anything to do with the issue though.
12:22, EET
April 3, 2012
Offline
Still no success in reproducing.. however adding a NodeManager addition and init (we need to added better error message if trying to add before that..) it did seem to cause “random stops” for a second or so, also it seemed that once it took more than 10 seconds, but I was not able to get that to happen again..
There is something different between your and my log..
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection – onStateTransition: Open->Closing
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: channel.isRegistered()=true
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: channel.isOpen()=true
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – closed
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: ownsSelector=false
01/08/2016 12:42:54.027 DEBUG [Selector] org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection – onStateTransition: Closing->Closed
01/08/2016 12:42:54.027 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection – CloseSecureChannelRequest
01/08/2016 12:42:54.028 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection – onStateTransition: Closed->Closing
01/08/2016 12:42:54.028 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: channel.isRegistered()=false
01/08/2016 12:42:54.028 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: channel.isOpen()=false
01/08/2016 12:42:54.028 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel – close: ownsSelector=false
01/08/2016 12:42:54.028 DEBUG [Blocking-Work-Executor-45] org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection – onStateTransition: Closing->Closed
Mine is going from Open to Closing whjle yours was from Closed to Closing. Also mine is in the Selector Thread..
I am testing this on windows 7 64bit on oracle’s JDK 8u45, which OS and jvm you are using?
If possible, can you send the full log by mail with:
log4j.logger.com.prosysopc.ua=INFO
(and I assume you already have log4j.logger.org.opcfoundation.ua.transport.tcp.nio.OpcTcpServerConnection=DEBUG
log4j.logger.org.opcfoundation.ua.utils.asyncsocket.ListenableSocketChannel=DEBUG)
How are you shutting down the server? (i.e. is it similar to the code I posted earlier)
I would assume the problem is that in some test the socket or something is not closed properly and would prevent the server from starting, because starting the server and all related activities should happen on the thread calling the .start. Assuming the client is connected in the same thread after that, I don’t see how the server would not be started. The UaServer.start should throw exception if it does not start so the client should not be connecting then. Still not sure why you see the connection problem of the client and not of the starting server, maybe there is a bug somewhere after all..
8:02, EET
March 18, 2014
Offline
Thank you for investigating. I will enable more logging and come back with more logs when I have reproduced the issue again. I’m not sure why we are seeing other thread names than you. As far as I can see, we are creating and shutting down everything on the same thread.
We’re running Prosys SDK 2.2.0-552 and JDK 1.8.0_66
8:27, EET
March 18, 2014
Offline
Here’s a full log from a failing run:
2016-01-12 09:14:02,408 INFO [UaApplication ] [main] Prosys OPC UA Java SDK v2.2.0-552
2016-01-12 09:14:02,409 INFO [UaApplication ] [main] (c) Prosys PMS Ltd.
2016-01-12 09:14:02,924 INFO [ApplicationIdentity ] [main] Creating a new application certificate & private key
2016-01-12 09:14:03,981 INFO [CryptoUtil ] [main] SecurityProvider initialized from org.bouncycastle.jce.provider.BouncyCastleProvider
2016-01-12 09:14:03,982 INFO [CryptoUtil ] [main] Using SecurityProvider BC
2016-01-12 09:14:04,118 INFO [ApplicationIdentity ] [main] Created a new Certificate: O=Sample Organisation, CN=MockServer; ApplicationURI=urn:host:UA:127.0.0.1 KeySize=2048
2016-01-12 09:14:04,374 INFO [NodeManagerTable ] [main] Loading model from jar:file:/path/prosys-opc-ua-java-sdk-client-server-binary/2.2.0-552/prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar!/com/prosysopc/ua/server/Opc.Ua.NodeSet2.xml
2016-01-12 09:14:06,734 INFO [UaServer ] [main] Server endpoint: opc.tcp://host:62897 [[http://opcfoundation.org/UA/SecurityPolicy#None,None], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,SignAndEncrypt], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,SignAndEncrypt]]
2016-01-12 09:14:06,752 INFO [OpcTcpServer ] [main] TCP/IP Socket bound to /127.0.0.1:62897
2016-01-12 09:14:06,754 INFO [OpcTcpServer ] [main] TCP/IP Socket bound to /ip-address:62897
2016-01-12 09:14:06,755 INFO [UaServer ] [main] Endpoint bound to: [127.0.0.1:62897, ip-address:62897]
2016-01-12 09:14:06,915 INFO [ApplicationIdentity ] [main] Creating a new application certificate & private key
2016-01-12 09:14:07,375 INFO [ApplicationIdentity ] [main] Created a new Certificate: O=Sample Organisation, CN=client; ApplicationURI=urn:host:UA:client KeySize=2048
2016-01-12 09:14:07,400 INFO [TcpConnection ] [main] localhost/127.0.0.1:62897 Connecting
2016-01-12 09:14:07,428 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] ListenableSocketChannel: channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:62897 remote=/127.0.0.1:42732]
2016-01-12 09:14:07,435 INFO [OpcTcpServer ] [Non-Blocking-Work-Executor-2] OpcTcpServer(opc.tcp(/127.0.0.1:62897, (opc.tcp://host:62897 [[http://opcfoundation.org/UA/SecurityPolicy#None,None], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,SignAndEncrypt], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,SignAndEncrypt]]))opc.tcp(/ip-address:62897, (opc.tcp://host:62897 [[http://opcfoundation.org/UA/SecurityPolicy#None,None], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,SignAndEncrypt], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,SignAndEncrypt]]))): /127.0.0.1:42732 connected
2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] onHello: url=
2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] endpoints=[opc.tcp://host:62897 [[http://opcfoundation.org/UA/SecurityPolicy#None,None], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,SignAndEncrypt], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,SignAndEncrypt]]]
2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] endpoint= [[http://opcfoundation.org/UA/SecurityPolicy#None,None], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15,SignAndEncrypt], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,Sign], [http://opcfoundation.org/UA/SecurityPolicy#Basic256,SignAndEncrypt]]
2016-01-12 09:14:07,455 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] onStateTransition: Closed->Opening
2016-01-12 09:14:07,459 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-2] addConnectionListener: listener=org.opcfoundation.ua.transport.tcp.nio.OpcTcpServer$1$1@2d820983
2016-01-12 09:14:07,496 INFO [TcpConnection ] [main] localhost/127.0.0.1:62897 Connect failed
org.opcfoundation.ua.common.ServiceResultException: Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)
at org.opcfoundation.ua.transport.tcp.io.TcpConnection.open(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
at org.opcfoundation.ua.transport.tcp.io.SecureChannelTcp.open(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
at org.opcfoundation.ua.application.Client.createSecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
at org.opcfoundation.ua.application.Client.createSecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
at org.opcfoundation.ua.application.Client.createSecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
at com.prosysopc.ua.client.UaClient.discoverEndpoints(Unknown Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
at com.prosysopc.ua.client.UaClient.discoverEndpoints(Unknown Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
at com.prosysopc.ua.client.UaClient.getEndpoints(Unknown Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
at com.prosysopc.ua.client.UaClient.t(Unknown Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
at com.prosysopc.ua.client.UaClient.connect(Unknown Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
2016-01-12 09:14:07,496 WARN [SecureChannelTcp ] [main] Connection failed: Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)
2016-01-12 09:14:07,497 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] onStateTransition: Opening->Closing
2016-01-12 09:14:07,498 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isRegistered()=true
2016-01-12 09:14:07,499 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: channel.isOpen()=true
2016-01-12 09:14:07,500 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] closed
2016-01-12 09:14:07,502 DEBUG [ListenableSocketChannel ] [Non-Blocking-Work-Executor-1] close: ownsSelector=false
2016-01-12 09:14:07,502 DEBUG [OpcTcpServerConnection ] [Non-Blocking-Work-Executor-1] onStateTransition: Closing->Closed
2016-01-12 09:14:07,503 DEBUG [OpcTcpServerConnection ] [Selector] onStateTransition: Closed->Closing
2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel ] [Selector] close: channel.isRegistered()=true
2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel ] [Selector] close: channel.isOpen()=false
2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel ] [Selector] close: ownsSelector=false
2016-01-12 09:14:07,503 DEBUG [OpcTcpServerConnection ] [Selector] onStateTransition: Closing->Closed
2016-01-12 09:14:08,525 INFO [UaServer ] [main] Shutdown: Delay (s)=1; Reason=(en) Closed by user
2016-01-12 09:14:08,525 INFO [Server ] [main] Server Server urn:host:UA:127.0.0.1 closed
2016-01-12 09:14:09,535 INFO [Server ] [main] Server Server urn:host:UA:127.0.0.1 closed
2016-01-12 09:14:09,536 INFO [OpcTcpServer ] [main] null closed
11:28, EET
March 18, 2014
Offline
Have you been able to investigate this further?
12:27, EET
April 3, 2012
Offline
I sent you mail on 13.1.
“
Hi,
Still no luck in reproducing the problem.
2016-01-12 09:14:07,496 INFO [TcpConnection ] [main] localhost/127.0.0.1:62897 Connect failed
org.opcfoundation.ua.common.ServiceResultException: Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)
I need to know where this came from. I would suspect the server side, but anyway the current log is not enough.
Can you log a version with both the Stack and the SDK on DEBUG (for all)?
“
+ instructions on how to upload the log file, as it most likely is too large for email attachment
There is not much I can do without knowing why that happens.
Most Users Ever Online: 518
Currently Online:
15 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: 683
Moderators: 16
Admins: 1
Forum Stats:
Groups: 3
Forums: 15
Topics: 1467
Posts: 6261
Newest Members:
digitechroshni, LouieWreve, Kickbiche, karrimacvitie5, graciela2073, sagarchau, elviralangwell4, Donnavek, Eddiefauth, DonaldPoomaModerators: Jouni Aro: 1010, 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
