Callback when server is initialized/shutdown | OPC UA SDK for JavaProsys Forum

Please consider registering
guest

Forum

OPC UA SDK for Java
sp_ArrowRight

Callback when server is initialized/shutdown

Topic RSS

Callback when server is initialized/shutdown

December 15, 2015
8:27, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
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?

December 15, 2015
9:26, EET

Bjarne Boström

Moderator

Moderators

Forum Posts: 1027

Member Since:
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

December 15, 2015
9:37, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
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.

December 16, 2015
11:14, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
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.”)”)”

January 4, 2016
8:54, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
March 18, 2014

Offline

Can anyone please confirm if this is a bug or expected behaviour?

January 5, 2016
10:48, EET

Bjarne Boström

Moderator

Moderators

Forum Posts: 1027

Member Since:
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.

public class RaceConditionTest {

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

January 7, 2016
13:48, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
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.

January 8, 2016
12:22, EET

Bjarne Boström

Moderator

Moderators

Forum Posts: 1027

Member Since:
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..

January 12, 2016
8:02, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
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

January 12, 2016
8:27, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
March 18, 2014

Offline

Here’s a full log from a failing run:

2016-01-12 09:14:02,408 INFO [UaApplication 2016-01-12 09:14:02,409 INFO [UaApplication 2016-01-12 09:14:02,924 INFO [ApplicationIdentity 2016-01-12 09:14:03,981 INFO [CryptoUtil 2016-01-12 09:14:03,982 INFO [CryptoUtil 2016-01-12 09:14:04,118 INFO [ApplicationIdentity 2016-01-12 09:14:04,374 INFO [NodeManagerTable 2016-01-12 09:14:06,734 INFO [UaServer 2016-01-12 09:14:06,752 INFO [OpcTcpServer 2016-01-12 09:14:06,754 INFO [OpcTcpServer 2016-01-12 09:14:06,755 INFO [UaServer 2016-01-12 09:14:06,915 INFO [ApplicationIdentity 2016-01-12 09:14:07,375 INFO [ApplicationIdentity 2016-01-12 09:14:07,400 INFO [TcpConnection 2016-01-12 09:14:07,428 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,435 INFO [OpcTcpServer 2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,450 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,455 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,459 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,496 INFO [TcpConnection org.opcfoundation.ua.common.ServiceResultException: at org.opcfoundation.ua.transport.tcp.io.TcpConne at org.opcfoundation.ua.transport.tcp.io.SecureCh at org.opcfoundation.ua.application.Client.create at org.opcfoundation.ua.application.Client.create at org.opcfoundation.ua.application.Client.create at com.prosysopc.ua.client.UaClient.discoverEndpoints(Unknown at com.prosysopc.ua.client.UaClient.discoverEndpoints(Unknown at com.prosysopc.ua.client.UaClient.getEndpoints(Unknown at com.prosysopc.ua.client.UaClient.t(Unknown at com.prosysopc.ua.client.UaClient.connect(Unknown 2016-01-12 09:14:07,496 WARN [SecureChannelTcp 2016-01-12 09:14:07,497 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,498 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,499 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,500 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,502 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,502 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,503 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,503 DEBUG [ListenableSocketChannel 2016-01-12 09:14:07,503 DEBUG [OpcTcpServerConnection 2016-01-12 09:14:08,525 INFO [UaServer 2016-01-12 09:14:08,525 INFO [Server 2016-01-12 09:14:09,535 INFO [Server 2016-01-12 09:14:09,536 INFO [OpcTcpServer ] [main] Prosys OPC UA Java SDK v2.2.0-552
] [main] (c) Prosys PMS Ltd.
] [main] Creating a new application certificate & private key
] [main] SecurityProvider initialized from org.bouncycastle.jce.provider.BouncyCastleProvider
] [main] Using SecurityProvider BC
] [main] Created a new Certificate: O=Sample Organisation, CN=MockServer; ApplicationURI=urn:host:UA:127.0.0.1 KeySize=2048
] [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
] [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]]
] [main] TCP/IP Socket bound to /127.0.0.1:62897
] [main] TCP/IP Socket bound to /ip-address:62897
] [main] Endpoint bound to: [127.0.0.1:62897, ip-address:62897]
] [main] Creating a new application certificate & private key
] [main] Created a new Certificate: O=Sample Organisation, CN=client; ApplicationURI=urn:host:UA:client KeySize=2048
] [main] localhost/127.0.0.1:62897 Connecting
] [Non-Blocking-Work-Executor-1] ListenableSocketChannel: channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:62897 remote=/127.0.0.1:42732]
] [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
] [Non-Blocking-Work-Executor-1] onHello: url=
] [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]]]
] [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]]
] [Non-Blocking-Work-Executor-2] onStateTransition: Closed->Opening
] [Non-Blocking-Work-Executor-2] addConnectionListener: listener=org.opcfoundation.ua.transport.tcp.nio.OpcTcpServer$1$1@2d820983
] [main] localhost/127.0.0.1:62897 Connect failed
Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)
ction.open(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
annelTcp.open(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
SecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
SecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
SecureChannel(Unknown Source) [opc.ua.stack-1.02.337.4.jar:1.02.337.4]
Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
Source) [prosys-opc-ua-java-sdk-client-server-binary-2.2.0-552.jar:2.2.0.552]
] [main] Connection failed: Bad_UnexpectedError (code=0x80010000, description=”Bad_UnexpectedError (code=0x80010000, description=”An unexpected error occurred.”)”)
] [Non-Blocking-Work-Executor-1] onStateTransition: Opening->Closing
] [Non-Blocking-Work-Executor-1] close: channel.isRegistered()=true
] [Non-Blocking-Work-Executor-1] close: channel.isOpen()=true
] [Non-Blocking-Work-Executor-1] closed
] [Non-Blocking-Work-Executor-1] close: ownsSelector=false
] [Non-Blocking-Work-Executor-1] onStateTransition: Closing->Closed
] [Selector] onStateTransition: Closed->Closing
] [Selector] close: channel.isRegistered()=true
] [Selector] close: channel.isOpen()=false
] [Selector] close: ownsSelector=false
] [Selector] onStateTransition: Closing->Closed
] [main] Shutdown: Delay (s)=1; Reason=(en) Closed by user
] [main] Server Server urn:host:UA:127.0.0.1 closed
] [main] Server Server urn:host:UA:127.0.0.1 closed
] [main] null closed

February 4, 2016
11:28, EET

Nils-H

Member

Members

Forum Posts: 21

Member Since:
March 18, 2014

Offline

Have you been able to investigate this further?

February 4, 2016
12:27, EET

Bjarne Boström

Moderator

Moderators

Forum Posts: 1027

Member Since:
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.

All RSS

Forum Timezone: Europe/Helsinki

Most Users Ever Online: 1919

Currently Online:
22 Guest(s)

Currently Browsing this Page:
1 Guest(s)