Log In
Home
05/30/2017
Offline
OK - the session is being closed for some reason.
Are there any other logs that say why the session is closed?
11/15/2021
Offline
Unfortunately no, the logs you see, were the final report before the connection closed.
Sometime I receive this logs:
27.04.22,13:02:11.8,INFO; Publish Error in Session: ns=1;i=1268930587; Statuscode: BadSecureChannelClosed
27.04.22,13:02:11.8,INFO; Publish Error in Session: ns=1;i=1268930587; Statuscode: BadSecureChannelClosed
27.04.22,13:02:12.9,INFO; Publish Error in Session: ns=1;i=1268930587; Statuscode: BadTcpInternalError
27.04.22,13:02:26.8,INFO;OPC_UA connection ended;SessionNr: ns=1;i=1268930587;Message: BadSessionIdInvalid
I am thinking of the symmetric key validity of the connection as the topic below:
05/30/2017
Offline
BadTcpInternalError indicates the connect was forcefully closed.
This could be expired keys but the code should automatically renew.
Have you fixed the clock on your PLC?
The clock should not affect key expiry since that is based on relative time.
11/15/2021
Offline
I have fixed the clock. The 2 hours late was because the plc is always set with 0 UTC.
Do I have to implement the key renew or it is already there as a property?
05/30/2017
Offline
key renew is automatic.
changing the clock can interrupt channels.
so it seems that the session is closing unexpectedly.
this could be clock related or an unreliable server.
i assume you do not have access to the server side logs on the PLC?
the client should automatically reconnect and re-create the subscriptions on unexpected failure.
this is not happening for some reason.
I need to find someone more familiar with the APIs.
11/15/2021
Offline
I have the log file on PLC right here but unfortunately it is German but I can translate.
17:10:45.917 28.04.2022 event OPC UA-Server: Session-Status changed to Timeout - Session-ID: 1109037720.
17:10:45.937 28.04.2022 event OPC UA-Server: Session-Status changed to Closed - Session-ID: 1109037720.
17:10:58.026 28.04.2022 event OPC UA-Server: Session-Status wrong use of Service ActivateSession in Session-ID: 0.
17:10:58.026 28.04.2022 event OPC UA-Server: Session-Error with Status: 16#80250000 in Session-ID: 0.
05/30/2017
Offline
That is useful.
The session has timed out.
On the Session object monitor:
SessionTimeout
KeepAliveInterval
KeepAliveStopped
LastKeepAliveTime
When you create the session if Info logs are on you should get this trace:
Utils.Trace("Revised session timeout value: {0}. ", m_sessionTimeout);
11/15/2021
Offline
I don't see any property or parameter as Info log in session creation. Perhaps it has other name.
Public Shared Function Create(configuration As ApplicationConfiguration, endpoint As ConfiguredEndpoint, updateBeforeConnect As Boolean, sessionName As String, sessionTimeout As UInteger, identity As IUserIdentity, preferredLocales As IList(Of String)) As Session
what is that Utils object you mentioned?
05/30/2017
Offline
They are properties on the Session object that are set after Create() is called.
Utils is helper class, there is a line in the code that prints that trace already.
You have to look for it.
11/15/2021
Offline
Which version of .NET API you have? I have browse the meta data of Session class and haven't found any instance of utils.
05/30/2017
Offline
It is a separate static class. You do not need to use it. The call is already in the code. You need to find the text "Revised session timeout value: " in the client log.
11/15/2021
Offline
Hi,
I found the code Utils.LogInfo("Revised session timeout value: {0}. ", m_sessionTimeout) in the function Open. However I am letting the OPC UA Client running as windows service. Is there anyway I can get that trace?
05/30/2017
Offline
Make sure the log file directory is writable by the windows account that your service uses.
11/15/2021
Offline
I have successfully let the trace print out.
This is the log when the opcua connection is create. Somehow there is always exception in OnReadComplete, although this doesn't affect the connection:
2000 - 5/2/2022 11:49:58.918 FindServers Called. RequestHandle=1, PendingRequestCount=1
2000 - 5/2/2022 11:49:59.059 Token #0 created. CreatedAt = 09:49:59.059 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.137 SECURE CHANNEL CREATED [TcpClientChannel UA-TCP 1.03.341.0] [ID=427002006] Connected To: opc.tcp://192.168.10.21:4840/ [None/None/Binary]
2000 - 5/2/2022 11:49:59.137 Token #1 activated. CreatedAt = 09:49:59.059 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.184 FindServers Completed. RequestHandle=1, PendingRequestCount=0
2000 - 5/2/2022 11:49:59.293 Unexpected error during OnReadComplete, SocketException 'An existing connection was forcibly closed by the remote host'
========================================
Id: Bad
Description: An existing connection was forcibly closed by the remote host
>>> An existing connection was forcibly closed by the remote host
--- at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
--- at Opc.Ua.Bindings.TcpMessageSocket.DoReadComplete(IAsyncResult result)
--- at Opc.Ua.Bindings.TcpMessageSocket.OnReadComplete(IAsyncResult result)
========================================
2000 - 5/2/2022 11:49:59.293 TCPCLIENTCHANNEL SOCKET CLOSED: 000006F0, ChannelId=427002006
02.05.2022 11:49:59;;INFO;connectToEndpoint, Aufruf
02.05.2022 11:49:59;;INFO;connectToEndpoint, A-Daten, URL: opc.tcp://192.168.10.21:4840/ / Benutzername: / SPSName: ServerInterfaces / DB: / Station:
02.05.2022 11:49:59;;INFO;Session nicht disposed
2000 - 5/2/2022 11:49:59.309 GetEndpoints Called. RequestHandle=1, PendingRequestCount=1
2000 - 5/2/2022 11:49:59.355 Token #0 created. CreatedAt = 09:49:59.355 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.387 SECURE CHANNEL CREATED [TcpClientChannel UA-TCP 1.03.341.0] [ID=427002007] Connected To: opc.tcp://192.168.10.21:4840/ [None/None/Binary]
2000 - 5/2/2022 11:49:59.387 Token #1 activated. CreatedAt = 09:49:59.355 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.434 GetEndpoints Completed. RequestHandle=1, PendingRequestCount=0
2000 - 5/2/2022 11:49:59.465 Unexpected error during OnReadComplete, SocketException 'An existing connection was forcibly closed by the remote host'
========================================
Id: Bad
Description: An existing connection was forcibly closed by the remote host
>>> An existing connection was forcibly closed by the remote host
--- at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
--- at Opc.Ua.Bindings.TcpMessageSocket.DoReadComplete(IAsyncResult result)
--- at Opc.Ua.Bindings.TcpMessageSocket.OnReadComplete(IAsyncResult result)
========================================
2000 - 5/2/2022 11:49:59.465 TCPCLIENTCHANNEL SOCKET CLOSED: 00000788, ChannelId=427002007
2000 - 5/2/2022 11:49:59.496 CreateSession Called. RequestHandle=1, PendingRequestCount=1
2000 - 5/2/2022 11:49:59.574 Token #0 created. CreatedAt = 09:49:59.574 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.590 SECURE CHANNEL CREATED [TcpClientChannel UA-TCP 1.03.341.0] [ID=427002008] Connected To: opc.tcp://192.168.10.21:4840/ [None/None/Binary]
2000 - 5/2/2022 11:49:59.590 Token #1 activated. CreatedAt = 09:49:59.574 . Lifetime = 3600000
2000 - 5/2/2022 11:49:59.746 CreateSession Completed. RequestHandle=1, PendingRequestCount=0
2000 - 5/2/2022 11:49:59.762 Revised session timeout value: 30000.
2000 - 5/2/2022 11:49:59.762 Max response message size value: 1048576. Max request message size: 0
2000 - 5/2/2022 11:49:59.762 Server signature is null or empty.
2000 - 5/2/2022 11:49:59.762 ActivateSession Called. RequestHandle=2, PendingRequestCount=1
2000 - 5/2/2022 11:49:59.808 ActivateSession Completed. RequestHandle=2, PendingRequestCount=0
2000 - 5/2/2022 11:49:59.808 Empty results were received for the ActivateSession call.
2000 - 5/2/2022 11:49:59.808 Read Called. RequestHandle=3, PendingRequestCount=1
2000 - 5/2/2022 11:49:59.855 Read Completed. RequestHandle=3, PendingRequestCount=0
2000 - 5/2/2022 11:49:59.855 Read Called. RequestHandle=1, PendingRequestCount=1
1 Guest(s)
Usage Policy