Problem with Subscription Timeouts (SubscriptionAliveListener.onTimeout) | OPC UA SDK for JavaProsys Forum

Please consider registering
guest

Forum

OPC UA SDK for Java
sp_ArrowRight

Problem with Subscription Timeouts (SubscriptionAliveListener.onTimeout)

Topic RSS

Problem with Subscription Timeouts (SubscriptionAliveListener.onTimeout)

June 27, 2018
9:37, EEST

Hendrik Ulbrich

Member

Members

Forum Posts: 14

Member Since:
June 27, 2018

Offline

Hello Prosys Team!
We currently have a problem in our OPC communication and are trying to find out whether the behavior is so correct and if not, whether client or server is the problem.
We use the Prosys Java SDK in version 2.3.2-781 and have developed an OPC-UA client. The following logs have been recorded under this version. We have now updated to version 3.1.4-514, but again we have the same error pattern.
We communicate via the client with a Siemens PLC with an OPC UA server running. The following information is available via the ServerStatusListener:
2018-06-27 07:42:27,859 TRACE C.OPCConnection$SSListener [PublishTask-com.prosysopc.ua.client.UaClient@1c932f2] OPCHandler.ServerStatusListener.onStatusChange: verbindung = opc_vssr_1 | status = ServerStatusDataType: ServerStatusDataType
StartTime=06/25/18 08:47:12.0591501 GMT
CurrentTime=06/27/18 05:42:15.8101121 GMT
State=ServerState
name=Running
ordinal=0
BuildInfo=BuildInfo
ProductUri=https://www.siemens.com/s7-1500
ManufacturerName=SIEMENS AG
ProductName=SIMATIC S7-1500 OPC UA
SoftwareVersion=V02.01.00
BuildNumber=00
BuildDate=01/01/01 00:00:00.0000000 GMT
SecondsTillShutdown=0
ShutdownReason=null

The general problem is that we get about 200 subscription timeouts (SubscriptionAliveLister.onTimeout) and we don’t think this is a common behavior. We have a few general questions about this:

– When exactly is a timeout detected by SubscriptionAliveListener?
– Can the timeout parameter be set in the client?
– Why are there so many timeouts even though the OPC server send a PublishResponse (UaClientListener.validatePublishResponse) at regular intervals of about 4 seconds?

The real problem is that between a timeout and an alive message from the SubscriptionAliveListener, the PublishResponses from the server are “ignored” although a data change has occurred.

Logs:

2018-06-25 11:14:44,419 FATAL m.OPCHandler$SAListener [PublishTask-com.prosysopc.ua.client.UaClient@e82563] OPCHandler.SubscriptionAliveListener.onTimeout: Subscription = {345=ClientHandle=345, MonitoredItemId=1, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Anfrage”.”Neue_Daten_an_MES”, AttributeId=Value, 346=ClientHandle=346, MonitoredItemId=2, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Anfrage”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 347=ClientHandle=347, MonitoredItemId=3, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Antwort”.”Neue_Daten_von_MES”, AttributeId=Value, 348=ClientHandle=348, MonitoredItemId=4, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Antwort”.”Neue_Daten_OK_an_MES”, AttributeId=Value, 349=ClientHandle=349, MonitoredItemId=5, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Anfrage”.”Neue_Daten_an_MES”, AttributeId=Value, 350=ClientHandle=350, MonitoredItemId=6, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Anfrage”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 351=ClientHandle=351, MonitoredItemId=7, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Antwort”.”Neue_Daten_von_MES”, AttributeId=Value, 352=ClientHandle=352, MonitoredItemId=8, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Antwort”.”Neue_Daten_OK_an_MES”, AttributeId=Value, 353=ClientHandle=353, MonitoredItemId=9, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Startmeldung”.”Neue_Daten_an_MES”, AttributeId=Value, 354=ClientHandle=354, MonitoredItemId=10, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Startmeldung”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 355=ClientHandle=355, MonitoredItemId=11, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusmeldung”.”Neue_Daten_an_MES”, AttributeId=Value, 356=ClientHandle=356, MonitoredItemId=12, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusmeldung”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 357=ClientHandle=357, MonitoredItemId=13, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusvorgabe”.”Neue_Daten_an_MES”, AttributeId=Value, 358=ClientHandle=358, MonitoredItemId=14, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusvorgabe”.”Neue_Daten_OK_von_MES”, AttributeId=Value}

2018-06-25 11:14:44,426 TRACE C.OPCConnection$UCListener [Blocking-Work-Executor-19] OPCHandler.UaClientListener.validatePublishResponse: verbindung = opc_vssr_1 | client = com.prosysopc.ua.client.UaClient@e82563 | response = PublishResponse
ResponseHeader=ResponseHeader
Timestamp=06/25/18 09:14:41.9414454 GMT
RequestHandle=1919469
ServiceResult=GOOD (0x00000000) “”
ServiceDiagnostics=Diagnostic Info:

StringTable=class java.lang.String[0]
AdditionalHeader=null
SubscriptionId=467659996
AvailableSequenceNumbers=class org.opcfoundation.ua.builtintypes.UnsignedInteger[1]
[0]=158
MoreNotifications=false
NotificationMessage=NotificationMessage
SequenceNumber=158
PublishTime=06/25/18 09:14:41.9414221 GMT
NotificationData=class org.opcfoundation.ua.builtintypes.ExtensionObject[1]
[0]=DataChangeNotification: DataChangeNotification
MonitoredItems=class org.opcfoundation.ua.core.MonitoredItemNotification[1]
[0]=MonitoredItemNotification
ClientHandle=355
Value=DataValue(value=true, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/25/18 09:14:41.8031107 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
DiagnosticInfos=class org.opcfoundation.ua.builtintypes.DiagnosticInfo[0]

Results=class org.opcfoundation.ua.builtintypes.StatusCode[0]
DiagnosticInfos=class org.opcfoundation.ua.builtintypes.DiagnosticInfo[0]

2018-06-25 11:14:44,551 TRACE m.OPCHandler$SAListener [PublishTask-com.prosysopc.ua.client.UaClient@e82563] OPCHandler.SubscriptionAliveListener.onAlive: Subscription = {345=ClientHandle=345, MonitoredItemId=1, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Anfrage”.”Neue_Daten_an_MES”, AttributeId=Value, 346=ClientHandle=346, MonitoredItemId=2, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Anfrage”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 347=ClientHandle=347, MonitoredItemId=3, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Antwort”.”Neue_Daten_von_MES”, AttributeId=Value, 348=ClientHandle=348, MonitoredItemId=4, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”DMC_Antwort”.”Neue_Daten_OK_an_MES”, AttributeId=Value, 349=ClientHandle=349, MonitoredItemId=5, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Anfrage”.”Neue_Daten_an_MES”, AttributeId=Value, 350=ClientHandle=350, MonitoredItemId=6, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Anfrage”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 351=ClientHandle=351, MonitoredItemId=7, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Antwort”.”Neue_Daten_von_MES”, AttributeId=Value, 352=ClientHandle=352, MonitoredItemId=8, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Par_Antwort”.”Neue_Daten_OK_an_MES”, AttributeId=Value, 353=ClientHandle=353, MonitoredItemId=9, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Startmeldung”.”Neue_Daten_an_MES”, AttributeId=Value, 354=ClientHandle=354, MonitoredItemId=10, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Startmeldung”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 355=ClientHandle=355, MonitoredItemId=11, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusmeldung”.”Neue_Daten_an_MES”, AttributeId=Value, 356=ClientHandle=356, MonitoredItemId=12, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusmeldung”.”Neue_Daten_OK_von_MES”, AttributeId=Value, 357=ClientHandle=357, MonitoredItemId=13, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusvorgabe”.”Neue_Daten_an_MES”, AttributeId=Value, 358=ClientHandle=358, MonitoredItemId=14, NodeId=ns=3;s=”DB_Tandem_Daten”.”L1_SB1″[0].”Steuerdaten”.”Statusvorgabe”.”Neue_Daten_OK_von_MES”, AttributeId=Value}

2018-06-25 11:14:46,561 TRACE C.OPCConnection$UCListener [Blocking-Work-Executor-15] OPCHandler.UaClientListener.validatePublishResponse: verbindung = opc_vssr_1 | client = com.prosysopc.ua.client.UaClient@e82563 | response = PublishResponse
ResponseHeader=ResponseHeader
Timestamp=06/25/18 09:14:46.1414248 GMT
RequestHandle=1919474
ServiceResult=GOOD (0x00000000) “”
ServiceDiagnostics=Diagnostic Info:

We get a timeout at 2018-06-25 11:14:44,419. At 2018-06-25 11:14:44,426 comes a PublishResponse which is recognized in UaClientListener.validatePublishResponse but does not trigger in SubscriptionNotificationListener.onDataChange. At 2018-06-25 11:14:44,551 we get an alive message but did not notice the previous data change, because in our client logic, the SubscriptionNotificationListener.onDataChange is the event that changes the data. After that we get the next message at 2018-06-25 11:14:46,561 and it runs until the next timeout without problems.

– Is it correct that in a timeout phase no onDataChange will be triggered, even if PublishRespones come from the server?

February 15, 2022
12:05, EET

Oleksandr

Member

Members

Forum Posts: 34

Member Since:
February 14, 2020

Offline

Hello,
we have the same case with our customers. Can you please answer the question?
Is it correct that in a timeout phase no onDataChange will be triggered, even if PublishRespones come from the server?
We also want to record the Wiresharkstreams logs.
Thank you
Oleksandr

February 16, 2022
13:12, EET

Bjarne Boström

Moderator

Moderators

Forum Posts: 1026

Member Since:
April 3, 2012

Offline

Hi,

I can say that it was resolved via email as far as I remember, sorry for not updating this post (note that I cannot go to specifics, but this should give a general idea based on the info of the first post).

I’m assuming you have a relatively recent 4.x version of the SDK, but in general always do include the used version plus sometimes we know of issues of some serves so it will help if you can say what the server in question is (from example, many Siemens S7 issues can be resolved by updating the firmware of the PLC, at least in Structure-related problems). We have done fixes to our SDK as well during the years so in general updating to the latest one is always recommended.

In general is is really hard to determine “it is the same case” in the case of subscription problems, it depends on so many things. It would be probably better to make completely new topic.

Anway …,
SubscriptionAliveListener.onTimeout and onLifetimeTimeout are client-side calculated “warnings” that something is wrong. The onTimeout happens if we didn’t see any activity in the “keepalive” period (meaning no data nor keepalives was received in X time which is a detection factor times publishinterval times maxkeepalivecount). Same for onLifetimeTimeout, but uses LifetimeCount instead of MaxKeepAliveCount. The onTimeout means server should still have the subscription per OPC UA rules, onLifetimeTimeout that it should have been deleted by the server at that point. Basically normally you should not see neither, as server should have sent a keepalive the very least.

The onTimeout is parallel to the data notifications etc. if a PublishResponse comes after onTimeout, you should just see the data. But it is an indication that something is most likely wrong with the server (might be just too slow), or that you have chosen too low MaxKeepAliveCount when compared to the PublishInterval. To offset network latency we have “detection factors” multiplied in the equations, but it is still “a guess” in a sense.

For example, if you make client side Subscription with defaults, but change publishinterval alone to e.g. 100ms, the keepalive would be only (the default) 20 (lifetime 60). This would give timeout window of 2 seconds and 6s for lifetime (not much). If you would try 10ms interval, they would be 200ms and 600ms -> very likely to happen (for example, if server processes subs sequentially and you would have a lot of them made, the very processing itself could be too slow and cause timeouts). If you have like 200 subscriptions, the number of them alone could pose problems for the server to handle, depending on the values.

You can configure our detection factors via Subscription.setTimeoutDetectionFactor (default is 1.3) and Subscription.setAliveDetectionFactor (default is 1.1). Keepalives and lifetime can be with Subscription.setMaxKeepAliveCount and setLifetimeCount or directly in the constructor. Please set them before adding the subscription to UaClient (they can be changed on runtime, but preferably do so before unless you intent to actively change them).

Note also that the 3 values: PublishInterval, MaxKeepAliveCount + LifetimeCount are “requests” to the server, it is allowed to revise them to ..basically any numbers (there are some rules, but it basically all depends on the server).

I believe this case was just solved mostly by increasing the MaxKeepAliveCount and allowing a higher detection factor. What exact numbers to use depends a lot on the case. As a rule of thumb, if you go lower than 1000 as publishinteval (the default), increase the keepalive from 20 (+lifetime as well). The more subscriptions you have, you might need to increase it more, depending if the server can keep up with them. The more there is network latency the more the detection factor might be need to be increased. Basically there isn’t exactly a “upper limit” to keepalivecount, but it gives more delay to note that something might be wrong (in OPC UA terms, on app level you might note it sooner if you know a data should be changing faster than you see it changing).

All RSS

Forum Timezone: Europe/Helsinki

Most Users Ever Online: 1919

Currently Online:
25 Guest(s)

Currently Browsing this Page:
1 Guest(s)