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}
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}
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.