UaTcpStackClient: Received PublishResponse for unknown requestHandle

When Ignitions OPC-UA client (V7.8.5) is used with a certain OPC-UA Server (Tani) the log is filled with warnings. Any ideas what might be causing this?

INFO   | jvm 2    | 2018/05/22 11:45:23 | WARN  [UaTcpStackClient              ] [11:45:23,490]: Received PublishResponse for unknown requestHandle: 106096
INFO   | jvm 2    | 2018/05/22 11:45:40 | WARN  [UaTcpStackClient              ] [11:45:40,003]: Received PublishResponse for unknown requestHandle: 106100
INFO   | jvm 2    | 2018/05/22 11:46:42 | WARN  [UaTcpStackClient              ] [11:46:42,279]: Received PublishResponse for unknown requestHandle: 106119
INFO   | jvm 2    | 2018/05/22 11:46:59 | WARN  [UaTcpStackClient              ] [11:46:59,044]: Received PublishResponse for unknown requestHandle: 106123
INFO   | jvm 2    | 2018/05/22 11:47:15 | WARN  [UaTcpStackClient              ] [11:47:15,660]: Received PublishResponse for unknown requestHandle: 106127
INFO   | jvm 2    | 2018/05/22 11:47:32 | WARN  [UaTcpStackClient              ] [11:47:32,171]: Received PublishResponse for unknown requestHandle: 106131
INFO   | jvm 2    | 2018/05/22 11:47:48 | WARN  [UaTcpStackClient              ] [11:47:48,696]: Received PublishResponse for unknown requestHandle: 106135
INFO   | jvm 2    | 2018/05/22 11:48:05 | WARN  [UaTcpStackClient              ] [11:48:05,402]: Received PublishResponse for unknown requestHandle: 106139
INFO   | jvm 2    | 2018/05/22 11:48:13 | WARN  [UaTcpStackClient              ] [11:48:13,682]: Received PublishResponse for unknown requestHandle: 106143
INFO   | jvm 2    | 2018/05/22 11:49:11 | WARN  [UaTcpStackClient              ] [11:49:11,968]: Received PublishResponse for unknown requestHandle: 106160
INFO   | jvm 2    | 2018/05/22 11:49:28 | WARN  [UaTcpStackClient              ] [11:49:28,426]: Received PublishResponse for unknown requestHandle: 106164
INFO   | jvm 2    | 2018/05/22 11:49:45 | WARN  [UaTcpStackClient              ] [11:49:45,046]: Received PublishResponse for unknown requestHandle: 106168
INFO   | jvm 2    | 2018/05/22 11:50:01 | WARN  [UaTcpStackClient              ] [11:50:01,831]: Received PublishResponse for unknown requestHandle: 106172

Consider setting up a trial of Ignition v7.9.x to see if it might be a fixed bug. If so, your only option would be to upgrade. Ignition v7.8 is not an LTS, and is not getting any more updates. If it’s reproducible on v7.9.x, it might be a Tani bug worth reporting. If it’s not hurting anything on your system, consider just turning that specific logger to “Warn” instead of “Info” to shut it up.

It means the client and server disagree about the frequency PublishResponses should be arriving. The client is timing them out and then sometime later they arrive.

Between 7.8 and latest 7.9 the way timeout, number of concurrent publish requests sent, and publishing interval are all derived has changed. It wasn’t known to be buggy, I just mention this to say that 7.9 is different enough that the error message may disappear in the newer versions.

I upgraded Ignition to 7.9.8 and the message ist still there.

The attached log shows that the ‘writeAndFlush’ entry is missing for those unmatched responses. Without digging deeper in the Milo code, it looks like sendRequest fails somehow and removes the request even though the request has been sent to the server.
Apart from that, the long time span between the request and the unmatched response is suspicious.

INFO   | jvm 1    | 2018/06/13 10:05:40 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:05:40]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1133  
INFO   | jvm 1    | 2018/06/13 10:05:50 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:05:50]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1134 
INFO   | jvm 1    | 2018/06/13 10:05:54 | W [o.e.m.o.s.c.UaTcpStackClient  ] [08:05:54]: Received unmatched PublishResponse with requestHandle=1127, timestamp=DateTime{utcTime=131733579544354796, javaDate=Wed Jun 13 12:05:54 CEST 2018} 
INFO   | jvm 1    | 2018/06/13 10:06:00 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:00]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1136 
INFO   | jvm 1    | 2018/06/13 10:06:10 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:10]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1138 
INFO   | jvm 1    | 2018/06/13 10:06:20 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:20]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1139 
INFO   | jvm 1    | 2018/06/13 10:06:29 | W [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:29]: Received unmatched PublishResponse with requestHandle=1132, timestamp=DateTime{utcTime=131733579890481368, javaDate=Wed Jun 13 12:06:29 CEST 2018} 
INFO   | jvm 1    | 2018/06/13 10:06:30 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:30]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1141 
INFO   | jvm 1    | 2018/06/13 10:06:40 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:40]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1143 
INFO   | jvm 1    | 2018/06/13 10:06:46 | W [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:46]: Received unmatched PublishResponse with requestHandle=1135, timestamp=DateTime{utcTime=131733580062978226, javaDate=Wed Jun 13 12:06:46 CEST 2018} 
INFO   | jvm 1    | 2018/06/13 10:06:50 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:06:50]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1144 
INFO   | jvm 1    | 2018/06/13 10:07:00 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:00]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1146 
INFO   | jvm 1    | 2018/06/13 10:07:03 | W [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:03]: Received unmatched PublishResponse with requestHandle=1137, timestamp=DateTime{utcTime=131733580234019952, javaDate=Wed Jun 13 12:07:03 CEST 2018} 
INFO   | jvm 1    | 2018/06/13 10:07:10 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:10]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1148 
INFO   | jvm 1    | 2018/06/13 10:07:20 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:20]: writeAndFlush succeeded for request=ReadRequest, requestHandle=1149 
INFO   | jvm 1    | 2018/06/13 10:07:20 | T [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:20]: writeAndFlush succeeded for request=ReadRequest, requestHandle=113161  
INFO   | jvm 1    | 2018/06/13 10:07:20 | W [o.e.m.o.s.c.UaTcpStackClient  ] [08:07:20]: Received unmatched PublishResponse with requestHandle=1140, timestamp=DateTime{utcTime=131733580406643768, javaDate=Wed Jun 13 12:07:20 CEST 2018}

Do you see ‘writeAndFlush’ entries for any PublishRequests?

edit: if this is happening regularly for you, a Wireshark capture would probably help.

Yes, for another connection (different range of request handles) the PublishRequests are in the log.

I will try to catch some packets with wireshark.

Okay. At first glance, any write failure should be logged on DEBUG level, so you’d be seeing those in the logs as well…

I made a wireshark capture on a test system today. The request / response packages look ok to me. There was a request package for every unmatched response. There were no error messages in the log.
The unmatched responses happen much more often on the production systems, maybe the phenomenon is load related.

07:12:59	Response		15713
		Request		15719
07:13:10	Response		15714
		Request		15721
07:13:20	Respone			15717
		Request		15723
07:13:37	Request		15726
07:13:41	Response		15719
		Response		15721
		Request		15727
07:13:58	Request		15730
07:14:05	Response		15723		
07:14:11	Response		15726
		Request		15732
```

```
INFO   | jvm 1    | 2018/06/14 07:13:41 | W [o.e.m.o.s.c.UaTcpStackClient  ] [05:13:41]: Received unmatched PublishResponse with requestHandle=15719, timestamp=DateTime{utcTime=131734340257232072, javaDate=Thu Jun 14 09:13:45 CEST 2018} 
INFO   | jvm 1    | 2018/06/14 07:14:05 | W [o.e.m.o.s.c.UaTcpStackClient  ] [05:14:05]: Received unmatched PublishResponse with requestHandle=15723, timestamp=DateTime{utcTime=131734340499458170, javaDate=Thu Jun 14 09:14:09 CEST 2018} 
INFO   | jvm 1    | 2018/06/14 07:14:23 | W [o.e.m.o.s.c.UaTcpStackClient  ] [05:14:23]: Received unmatched PublishResponse with requestHandle=15727, timestamp=DateTime{utcTime=131734340683166396, javaDate=Thu Jun 14 09:14:28 CEST 2018}

2018-06-16-OPC-UA.zip (43.1 KB)

It appears to be an issue with the server not sending responses back in time.

Analyzing the Request/Response pair with requestHandle=15719, you can see the timeout hint in the RequestHeader of the PublishRequest is 37687 (milliseconds), but the PublishResponse does not arrive until ~41.5 seconds later.

The timeoutHint is already calculated with 25% extra padding on the worst-case time that should elapse between PublishResponses received from the server based on the subscription rates. “Worst-case” means no data is changing and it’s only the “keep alive” responses. And even when changing subscription rates lead to a timeoutHint on an already-queued request that can’t be honored, the server is supposed to dequeue it and send a Bad_Timeout service result, and then use the next request in the queue that isn’t timed out. It should not be sending back a PublishResponse for a PublishRequest it knows has timed out based on the timeoutHint.

2 Likes