# UaTcpStackClient: Received PublishResponse for unknown requestHandle **URL:** \ **Category:** Ignition\ **Created:** [May 22, 2018, 9:55am UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115 "2018-05-22T09:55:09Z")\ **Posts on this page:** 9\ **Page:** 1
**Author:** ![chi](https://avatars.discourse-cdn.com/v4/letter/c/0ea827/32.png) [@chi](https://forum.inductiveautomation.com/u/chi)\ **Post date:** [May 22, 2018, 9:55am UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/1 "2018-05-22T09:55:09Z")
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? ```auto 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 ``` ---
**Author:** ![pturmel](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/pturmel/32/3295_2.png) [@pturmel](https://forum.inductiveautomation.com/u/pturmel)\ **Post date:** [May 22, 2018, 12:05pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/2 "2018-05-22T12:05:04Z")
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. ---
**Author:** ![Kevin.Herron](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kevin.herron/32/7259_2.png) [@Kevin.Herron](https://forum.inductiveautomation.com/u/Kevin.Herron)\ **Post date:** [May 22, 2018, 12:18pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/3 "2018-05-22T12:18:06Z")
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. ---
**Author:** ![chi](https://avatars.discourse-cdn.com/v4/letter/c/0ea827/32.png) [@chi](https://forum.inductiveautomation.com/u/chi)\ **Post date:** [June 13, 2018, 11:38am UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/4 "2018-06-13T11:38:25Z")
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. ```auto 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} ``` ---
**Author:** ![Kevin.Herron](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kevin.herron/32/7259_2.png) [@Kevin.Herron](https://forum.inductiveautomation.com/u/Kevin.Herron)\ **Post date:** [June 13, 2018, 11:42am UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/5 "2018-06-13T11:42:41Z")
Do you see ‘writeAndFlush’ entries for _any_ PublishRequests? edit: if this is happening regularly for you, a Wireshark capture would probably help. ---
**Author:** ![chi](https://avatars.discourse-cdn.com/v4/letter/c/0ea827/32.png) [@chi](https://forum.inductiveautomation.com/u/chi)\ **Post date:** [June 13, 2018, 12:00pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/6 "2018-06-13T12:00:01Z")
> [@Kevin.Herron](#): > > Do you see 'writeAndFlush' entries for any PublishRequests? Yes, for another connection (different range of request handles) the PublishRequests are in the log. I will try to catch some packets with wireshark. ---
**Author:** ![Kevin.Herron](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kevin.herron/32/7259_2.png) [@Kevin.Herron](https://forum.inductiveautomation.com/u/Kevin.Herron)\ **Post date:** [June 13, 2018, 12:02pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/7 "2018-06-13T12:02:49Z")
Okay. At first glance, any write failure should be logged on DEBUG level, so you’d be seeing those in the logs as well… ---
**Author:** ![chi](https://avatars.discourse-cdn.com/v4/letter/c/0ea827/32.png) [@chi](https://forum.inductiveautomation.com/u/chi)\ **Post date:** [June 14, 2018, 1:36pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/8 "2018-06-14T13:36:50Z")
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. ````auto 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](https://us1.discourse-cdn.com/inductiveautomation/original/2X/b/b863f39637663b380c0ae951789899d5ab1348ee.zip) (43.1 KB) ---
**Author:** ![Kevin.Herron](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kevin.herron/32/7259_2.png) [@Kevin.Herron](https://forum.inductiveautomation.com/u/Kevin.Herron)\ **Post date:** [June 15, 2018, 3:32pm UTC](https://forum.inductiveautomation.com/t/uatcpstackclient-received-publishresponse-for-unknown-requesthandle/18115/9 "2018-06-15T15:32:57Z")
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.