Binding Request: LinkTap

dagoodyear · January 13, 2025, 10:46pm

Still trying to replicate. I setup a new VM on our servers (VirtualBox didn’t play ball on my laptop), installed 4.3.2 (will try and find a way to get 4.3.1 instead and retest after restoring the fresh OS image). So far I’ve seen the other bug’s, but nothing relating to the bridge going online and offline.

I take it the bridge was not auto-discovered, and you did Add Bridge, and then added it by its IP in the UI. (Just to rule out mdns related bits)? Sorry do you mean the Tap or the Gateway was auto-discovered?

At the moment I’m wondering if one of the other dependencies took a while to start, but then I’d be surprised if you didn’t get a different error in the logs.

Okay I got 4.3.0-1 installed and soak testing now. Just one other question - do you use authentication on the web interface for the Gateway or is it unset?

P.S I’ve had one through about it now I’ve taken a step back the timeouts were changed to 3 seconds during the PR based on the very quick timings of the GW02 model. It may be the GW01 need’s longer - so am checking with LinkTap regarding this, and whether your unit happened to be firmware updating at that timestamp (just in case).

dagoodyear · February 2, 2025, 6:26pm

HI @Andy_Co,

I’ve been soak testing the GW02, with the original binding and the new build with the patches that will further help comm’s issues if the controller is busy. However both appear from the logged data not to have exhibited the fault now for several weeks. Have you had any further issues? Just checking as I’ll likely update the bug report, as it still need’s to go in but doesn’t seem to be as impacting as believed.

Andy_Co · May 10, 2025, 6:56am

Hi @dagoodyear ,

Probably after upgrading openhab to 5.0 M2 my Linktap Gateway stop responding. I tried changing configuration on Gateway itself and binding but with no success. I have such error:

**COMMUNICATION_ERROR**
Hostname / IP cannot be found

Gateway status is offline. Thing properties are as below:

hardwareModel
GW-01
macAddress
02-4B-29-1F-78-D6
httpApiCallback
http://192.168.1.110:8080/linktap
utcOffset
7200
version
S0609282504271201I
volumeUnit
L
httpApiEnabled
true
gatewayId
78D6291F004B1200

In trace logs I can find:

2025-05-10 08:53:10.028 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Not requesting MDNS Scan last ran under 10 min's ago
2025-05-10 08:53:10.029 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
2025-05-10 08:53:18.270 [DEBUG] [inktap.internal.TransactionProcessor] - f9766e3e-04c0-4bca-9c63-80c3749e7844 = GW -> APP Request 192.168.1.105 -> Payload {"cmd":3,"gw_id":"78D6291F004B1200","dev_stat":{"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":83,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}}
2025-05-10 08:53:18.273 [TRACE] [inktap.internal.TransactionProcessor] - Found bridge with ID: 78D6291F004B1200 -> LinkTap Gateway
2025-05-10 08:53:18.274 [DEBUG] [inktap.internal.TransactionProcessor] - No device with id 71577F1F004B1200 found to process command 3
2025-05-10 08:53:18.275 [DEBUG] [inktap.internal.TransactionProcessor] - f9766e3e-04c0-4bca-9c63-80c3749e7844 = GW -> APP Response {"cmd":3,"gw_id":"78D6291F004B1200","dev_stat":{"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":83,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}} -> Payload
2025-05-10 08:53:19.005 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Not requesting MDNS Scan last ran under 10 min's ago
2025-05-10 08:53:19.006 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
2025-05-10 08:53:19.007 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler LinkTapBridgeHandler tried updating the thing status although the handler was already disposed.

and

2025-05-10 08:54:00.080 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - a76e4e04-d916-4e1c-8d5c-57f6f14ba388 = APP BRIDGE -> GW -> Request {"cmd":16,"gw_id":"78D6291F004B1200"}
2025-05-10 08:54:00.081 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
2025-05-10 08:54:00.103 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - a76e4e04-d916-4e1c-8d5c-57f6f14ba388 = APP BRIDGE -> GW -> Response {"cmd":16,"gw_id":"78D6291F004B1200","ver":"S0609282504271201I","vol_unit":"L","utc_ofs":7200,"end_dev":["71577F1F004B1200"],"dev_name":["TapLinker"]}
2025-05-10 08:54:00.106 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania
2025-05-10 08:54:00.121 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Local address for connectivity is 192.168.1.110
2025-05-10 08:54:03.002 [TRACE] [g.linktap.protocol.http.WebServerApi] - Setting Local HTTP Api on gateway
2025-05-10 08:54:03.004 [TRACE] [g.linktap.protocol.http.WebServerApi] - Found existing HTTP URL Server : http://192.168.1.110:8080/linktap
2025-05-10 08:54:03.005 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - d52e5a6f-414f-4a1a-b4e5-fedfffe22fec = APP BRIDGE -> GW -> Request {"cmd":16,"gw_id":"78D6291F004B1200"}
2025-05-10 08:54:03.006 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
2025-05-10 08:54:03.023 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - d52e5a6f-414f-4a1a-b4e5-fedfffe22fec = APP BRIDGE -> GW -> Response {"cmd":16,"gw_id":"78D6291F004B1200","ver":"S0609282504271201I","vol_unit":"L","utc_ofs":7200,"end_dev":["71577F1F004B1200"],"dev_name":["TapLinker"]}
2025-05-10 08:54:03.024 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania
2025-05-10 08:54:03.024 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler LinkTapBridgeHandler tried updating the thing status although the handler was already disposed.
2025-05-10 08:54:03.028 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania

But the gateway is still offline - what can be wrong ?

dagoodyear · May 11, 2025, 12:25am

Andy_Co:

2025-05-10 08:53:18.274 [DEBUG] [inktap.internal.TransactionProcessor] - No device with id 71577F1F004B1200 found to process command 3
2025-05-10 08:53:18.275 [DEBUG] [inktap.internal.TransactionProcessor] - f9766e3e-04c0-4bca-9c63-80c3749e7844 = GW -> APP Response {"cmd":3,"gw_id":"78D6291F004B1200","dev_stat":{"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":83,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}} -> Payload
2025-05-10 08:53:19.005 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Not requesting MDNS Scan last ran under 10 min's ago

Hi @Andy_Co, apologies for the delay, many things going on atm, on all fronts with family / work / etc…

Looking at above, this is not a TapLink issue, the gateway is clearly online from your traces (Thank you! ), and the gateway is responding as necessary (so that removes issues from it being the device / communications elements of the binding). To explain a bit more - the system aims to conserve resources using a single set of shared memory to track everything, and let the binding know when devices have got comm’s / updates etc… aka its online, a taps on / off etc…

What’s going on with your trace above, at a first quick glance is that binding has detected the gateway has been detected and is online. However, the underlying OpenHab system has made a new setup of the system (at a guess - I need to trace / replicate the issue), so when the binding has seen its online, its gone to update what the binding knew was the OpenHab representation of the TapLink devices, but its been changed outside of the bindings knowledge - so it cant update it as its lost knowledge of what now represents your device. This could be a binding or OpenHab issue I need to dig a lot more.

For now: can you try giving it a reboot or alternatively you may be able to pause and un-pause the binding to restart it, after start-up. That should hopefully correct its internal state tracking to determine the correct state after whatever has changed is known about.

(Is this a consistent behaviour that you have seen, since using this build?)

I’ll install the same build here to see if I can replicate to trace the root issue / method to compensate. If possible can you advise on whether your CPU gets maxed out during start-up? I can adjust my computers here to simulate the same if you see your CPU usage amount going high for example. Windows task manager or the linux top command should give a indication.

I can think of a way to patch, but would prefer to first to understand what is really going on here as the root cause of the issue. Hopefully the pause and resume brings it on-line while I attempt to dig a bit more. If you have any idea on the CPU loading question that would be great, to help replicate the issue. If the issue is consistent, then sorry are you happy if in a worst case I send you custom builds to get more trace data from your systems, if I cannot replicate on my setup here?

Hopefully the pause and un-pause works as I hope.

Andy_Co · May 11, 2025, 7:22am

Thank You for answer. So I disabled the gateway, rebooted openhab and enabled gateway again. The error is now:

Status: 
OFFLINE
COMMUNICATION_ERROR
Cannot connect to LinkTap Gateway

Openhab is on Raspberry Pi 4 with 8 Gb of ram and quick SSD stick as storage. During startup processor load is up to 99%.

I attached log from startup in file (I grep the Linktap entries),
linktap.log (122.1 KB)
Thank You for help.

Andy_Co · May 11, 2025, 8:06am

And suddenly is working again:

	2025-05-11 09:46:28.219 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:46:46.221 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:47:04.223 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:47:14.155 [DEBUG] [inktap.internal.TransactionProcessor] - f8561cb0-04ac-46a5-bf10-df8d7d65079e = GW -> APP Request 192.168.1.105 -> Payload {"cmd":3,"gw_id":"78D6291F004B1200","dev_stat":{"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}}
	2025-05-11 09:47:14.157 [TRACE] [inktap.internal.TransactionProcessor] - Found bridge with ID: 78D6291F004B1200 -> LinkTap Gateway
	2025-05-11 09:47:14.159 [DEBUG] [inktap.internal.TransactionProcessor] - No device with id 71577F1F004B1200 found to process command 3
	2025-05-11 09:47:14.160 [DEBUG] [inktap.internal.TransactionProcessor] - f8561cb0-04ac-46a5-bf10-df8d7d65079e = GW -> APP Response {"cmd":3,"gw_id":"78D6291F004B1200","dev_stat":{"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}} -> Payload
	2025-05-11 09:47:22.226 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:47:40.228 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:47:58.230 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:48:16.233 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Scheduling connection re-attempt in 15 seconds
	2025-05-11 09:48:34.170 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - 8a4a7f3c-378c-4714-9186-08040a7fba9a = APP BRIDGE -> GW -> Request {"cmd":16,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:34.171 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:34.190 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - 8a4a7f3c-378c-4714-9186-08040a7fba9a = APP BRIDGE -> GW -> Response {"cmd":16,"gw_id":"78D6291F004B1200","ver":"S0609282504271201I","vol_unit":"L","utc_ofs":7200,"end_dev":["71577F1F004B1200"],"dev_name":["TapLinker"]}
	2025-05-11 09:48:34.193 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania
	2025-05-11 09:48:34.198 [TRACE] [inktap.internal.LinkTapBridgeHandler] - Local address for connectivity is 192.168.1.110
	2025-05-11 09:48:35.679 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [7842] Device found: shelly1pmminig3-84fce63f0510._http._tcp.local.
	2025-05-11 09:48:35.680 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [7842] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:35.680 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [5D64] Device found: shelly1pmminig3-84fce63f0510._http._tcp.local.
	2025-05-11 09:48:35.681 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [5D64] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:35.759 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [6302] Device found: Boczne Pitro Schody._http._tcp.local.
	2025-05-11 09:48:35.760 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [6302] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:35.761 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [1702] Device found: Boczne Pitro Schody._http._tcp.local.
	2025-05-11 09:48:35.761 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [1702] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:36.845 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [6DA3] Device found: shelly1pmminig3-84fce63f0510._http._tcp.local.
	2025-05-11 09:48:36.846 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [6DA3] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:36.846 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [24DF] Device found: shelly1pmminig3-84fce63f0510._http._tcp.local.
	2025-05-11 09:48:36.847 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [24DF] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:36.848 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [1CA5] Device found: shelly1pmminig3-84fce63f0510._http._tcp.local.
	2025-05-11 09:48:36.850 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [1CA5] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:37.065 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [5F47] Device found: Boczne Pitro Schody._http._tcp.local.
	2025-05-11 09:48:37.066 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [5F47] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:37.067 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [296F] Device found: Boczne Pitro Schody._http._tcp.local.
	2025-05-11 09:48:37.068 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [296F] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:37.082 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [7EBE] Device found: Boczne Pitro Schody._http._tcp.local.
	2025-05-11 09:48:37.082 [TRACE] [ternal.LinkTapBridgeDiscoveryService] - [7EBE] Not a LinkTap Gateway - wrong name
	2025-05-11 09:48:37.171 [TRACE] [g.linktap.protocol.http.WebServerApi] - Setting Local HTTP Api on gateway
	2025-05-11 09:48:37.172 [TRACE] [g.linktap.protocol.http.WebServerApi] - Enabling efficient non HTML communications on gateway
	2025-05-11 09:48:37.173 [TRACE] [g.linktap.protocol.http.WebServerApi] - Found existing HTTP URL Server : http://192.168.1.110:8080/linktap
	2025-05-11 09:48:37.174 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - e3864f7e-e797-4a50-9d8c-df7976347f97 = APP BRIDGE -> GW -> Request {"cmd":16,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:37.174 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:37.191 [DEBUG] [inktap.internal.LinkTapBridgeHandler] - e3864f7e-e797-4a50-9d8c-df7976347f97 = APP BRIDGE -> GW -> Response {"cmd":16,"gw_id":"78D6291F004B1200","ver":"S0609282504271201I","vol_unit":"L","utc_ofs":7200,"end_dev":["71577F1F004B1200"],"dev_name":["TapLinker"]}
	2025-05-11 09:48:37.193 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania
	2025-05-11 09:48:37.194 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.194 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.195 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.196 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.201 [TRACE] [ding.linktap.internal.LinkTapHandler] - Handling new bridge data for LinkTap Sterownik Podlewania
	2025-05-11 09:48:37.203 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.204 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.207 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.207 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.207 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.208 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.211 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.211 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.212 [DEBUG] [inktap.internal.TransactionProcessor] - f003970d-9a8e-40db-8b5d-da85798fe1cb = APP -> GW Request 192.168.1.105 -> Payload {"enable":true,"alert":0,"dev_id":"71577F1F004B1200","cmd":10,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:37.214 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:37.230 [DEBUG] [inktap.internal.TransactionProcessor] - f003970d-9a8e-40db-8b5d-da85798fe1cb = APP -> GW Response 192.168.1.105 -> Payload {"cmd":10,"gw_id":"78D6291F004B1200","dev_id":"71577F1F004B1200","ret":0}
	2025-05-11 09:48:37.231 [TRACE] [inktap.internal.TransactionProcessor] - Request successfully processed
	2025-05-11 09:48:37.232 [DEBUG] [inktap.internal.TransactionProcessor] - e6f45799-d651-46c1-9ae3-22479d0ce184 = APP -> GW Request 192.168.1.105 -> Payload {"enable":true,"alert":0,"dev_id":"71577F1F004B1200","cmd":10,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:37.233 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:37.251 [DEBUG] [inktap.internal.TransactionProcessor] - e6f45799-d651-46c1-9ae3-22479d0ce184 = APP -> GW Response 192.168.1.105 -> Payload {"cmd":10,"gw_id":"78D6291F004B1200","dev_id":"71577F1F004B1200","ret":0}
	2025-05-11 09:48:37.251 [TRACE] [inktap.internal.TransactionProcessor] - Request successfully processed
	2025-05-11 09:48:37.256 [DEBUG] [inktap.internal.TransactionProcessor] - 870fde4b-0231-4a62-b712-405d6d5bf838 = APP -> GW Request 192.168.1.105 -> Payload {"enable":true,"alert":0,"dev_id":"71577F1F004B1200","cmd":10,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:37.257 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:37.280 [DEBUG] [inktap.internal.TransactionProcessor] - 870fde4b-0231-4a62-b712-405d6d5bf838 = APP -> GW Response 192.168.1.105 -> Payload {"cmd":10,"gw_id":"78D6291F004B1200","dev_id":"71577F1F004B1200","ret":0}
	2025-05-11 09:48:37.281 [TRACE] [inktap.internal.TransactionProcessor] - Request successfully processed
	2025-05-11 09:48:37.986 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:37.986 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:37.988 [DEBUG] [inktap.internal.TransactionProcessor] - c3fb0d97-44dd-4d74-9f36-47a01566f60e = APP -> GW Request 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","cmd":3,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:37.988 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:38.011 [DEBUG] [inktap.internal.TransactionProcessor] - c3fb0d97-44dd-4d74-9f36-47a01566f60e = APP -> GW Response 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}
	2025-05-11 09:48:38.012 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:38.013 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:38.014 [DEBUG] [inktap.internal.TransactionProcessor] - 8de3ca63-5c3f-41b6-8f57-4aa67ca991ac = APP -> GW Request 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","cmd":3,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:38.015 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:38.038 [DEBUG] [inktap.internal.TransactionProcessor] - 8de3ca63-5c3f-41b6-8f57-4aa67ca991ac = APP -> GW Response 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}
	2025-05-11 09:48:38.039 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:38.040 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:38.040 [DEBUG] [inktap.internal.TransactionProcessor] - a2b0fc64-9540-49a7-a9fa-504bdb94d26e = APP -> GW Request 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","cmd":3,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:38.041 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:38.061 [DEBUG] [inktap.internal.TransactionProcessor] - a2b0fc64-9540-49a7-a9fa-504bdb94d26e = APP -> GW Response 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}
	2025-05-11 09:48:38.074 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:38.074 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:38.075 [DEBUG] [inktap.internal.TransactionProcessor] - df7a1099-c402-4d07-9ffb-e1ab3fcf590c = APP -> GW Request 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","cmd":3,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:38.076 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:38.092 [DEBUG] [inktap.internal.TransactionProcessor] - df7a1099-c402-4d07-9ffb-e1ab3fcf590c = APP -> GW Response 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}
	2025-05-11 09:48:38.092 [TRACE] [inktap.internal.PollingDeviceHandler] - Searching for device address id : 71577F1F004B1200
	2025-05-11 09:48:38.093 [TRACE] [inktap.internal.PollingDeviceHandler] - Using matched Address ID (dev_id) 71577F1F004B1200
	2025-05-11 09:48:38.094 [DEBUG] [inktap.internal.TransactionProcessor] - a742d517-c662-4cb2-bfd4-fd2faa72bba9 = APP -> GW Request 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","cmd":3,"gw_id":"78D6291F004B1200"}
	2025-05-11 09:48:38.094 [TRACE] [g.linktap.protocol.http.WebServerApi] - API Endpoint: http://192.168.1.105/api.shtml
	2025-05-11 09:48:38.111 [DEBUG] [inktap.internal.TransactionProcessor] - a742d517-c662-4cb2-bfd4-fd2faa72bba9 = APP -> GW Response 192.168.1.105 -> Payload {"dev_id":"71577F1F004B1200","plan_mode":5,"plan_sn":415716476,"is_rf_linked":true,"is_flm_plugin":true,"is_fall":false,"is_broken":false,"is_cutoff":false,"is_leak":false,"is_clog":false,"signal":82,"battery":60,"child_lock":0,"is_manual_mode":false,"is_watering":false,"is_final":false,"total_duration":0,"remain_duration":0,"speed":0.00,"volume":0.00,"volume_limit":0.00,"failsafe_duration":0}

dagoodyear · May 11, 2025, 2:16pm

Hi @Andy_Co thanks for all the logs. It’s helped in tracking it through - now I’ve worked through the process your systems following I can see why it didn’t know what the device is as, it looks like it had issues with the UI login to configure the GW-01, so it never got the point of registering what devices the LinkTap device has, so its not an issue where I originally though after first reading your message.

Given your on PI hardware running under heavy load, (even my vm’s do on the server I run it at during boot up), I’m literally wondering if it just doesn’t have enough time to process the request before presuming there’s a issue, and the connection attempt being considered bad. (It could also be if some other binding is preventing this one running the required bits to setup the GW-01 in a sensible time.

Unfortunately in the code bits like that are not logged to the detail I could do with here, so are you okay if I make a enriched M2 version of the binding with more trace logs in. This may be a case it just need’s more time on the timeouts for the GW-01 model and possibly due to the load’s on your system, but its hard to tell without additional traces if it’s the GW-01 miss-behaving (not strongly suspected - I would just like to rule it out - as I have a GW-02 so can’t test like for like), a hostname lookup issue, or the fact it just cant process the UI aspects quick enough.

Please advise if your okay to load on a build with more trace output added, then hopefully if this happens at the next restart or next time there will be more data to correlate. In the meantime I’m still looking though this.

Thanks again

David

dagoodyear · May 12, 2025, 1:01am

Hi @Andy_Co,

I’ve been analysing your logs and thinking this through. Its either likely something in the underlying jetty client the bindings using such as DNS failing, or more likely just a timing issue because the systems so busy, it cant hit the expected timings as its doing too many other things.

At the moment, I’ve tried several simulations limiting CPU, but have not yet replicated unfortunately with the GW-02. (I can see from your logs the FW didn’t change so I know at least it wasn’t due to a FW upgrade that got patched quickly).

I’ve raised a new PR for the binding to allow configuration for the timeouts to be changed by configuration. Previously it was 3 seconds, as the devices are much faster than that, from discussions with TapLink before. I suspect however the PI image / hardware may not behave the same way as my simulations even after I have slowed everything down as its x64 based here rather than ARM. (Unfortunately I have no PI4’s to use as they are all running critical bits I cant shutdown atm).

PR info for your reference: WIP: [linktap] Communications timeout configuration by dag81 · Pull Request #18679 · openhab/openhab-addons · GitHub

After this is reviewed I’ll post a link to the build (so the build published has the naming’s that will be in the final build - in case it changes, I’m hesitant to push right now).

After this is used I there’s two bits in the log’s should this happen again:

If there is no: “Validating response from Gateway web UI” message after the “Local address for connectivity is” message, then the gateway didn’t reply in the expected timeframe from what the binding can see. If this is the case does the web UI work in a response fashion - e.g. appear within the timeout setting. (Just in case its the GW-01).

If the web ui does appear, then its likely just a overloading issue, so there is a new configuration option against the bridge hopefully it will be called: gatewayRequestTimeout (pending code review so it could change slightly), this can be increased from 3 to say 10 seconds - maybe worst case try 30 seconds, if 10 still doesn’t work. If after adjusting (reboot just to be sure), if it still doesn’t show that Validating response from Gateway web ui, then it could be something with the GW-01, or variables outside of the binding. If this is the case logs from jetty should hopefully help (I’ll have to investigate how to enable them, but I’m pretty sure I’ve used them last year at some point - I’m hoping however increasing this setting and the time the system waits to get something processed back should cover the scenario that your seeing there).

I need to do a few final checks tomorrow to ensure its working as expected, then will open it up for review, once naming conventions are agreed I’ll post a build).

Andy_Co · May 12, 2025, 4:41pm

Hi, sounds good. Thak for support once again. Some clarification - such gigh load (up to 99%) is only when openhab is starting, after that is usually about 3-10%. And if I understood you correctly, I started openhab with disabled gateway thing, and enabled it when the CPU load was already low. Taking about the DNS - I have just local IP address in gateway configuration.

dagoodyear · May 12, 2025, 7:12pm

Yeah okay that’s key as well. In that case are you good to try a custom build to help get to the bottom of this, on researching jetty - the http client library it uses - other bindings could block it, so we need to find out if that’s a possible root cause. If I add more traces to when jetty queues, and executes the requests if they timeout before being executed then something else must be blocking the shared jetty client. If it is executing then we know potentially there’s something potentially suspect with the comms to the GW-01, however it must have responses before because it got the local address for your network, so I’m still leaning away from it being the GW01 device at the moment. A custom build would pin it down then to whether its device or something blocking the http lib from working?

dagoodyear · May 12, 2025, 11:50pm

Hi @Andy_Co,

I’ve submitted a few more updates to my PR - I’m hoping the changes will be acceptable. I know generally too much logging isn’t required. However if it is acceptable then in trace mode the binding will output something like this:

(My logic is I can see this problem happening in the future so its better to have something to identify the root cause, whether its the device or the system running it - in place when trace mode is enabled).

00:43:04.930 [TRACE] [linktap.internal.LinkTapBridgeHandler] - Local address for connectivity is 10.4.40.10
00:43:04.931 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is queued to be processed to http://10.90.3.2
00:43:04.943 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is beginning to be processed to http://10.90.3.2/
00:43:04.946 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request has been reported as successful to http://10.90.3.2/
00:43:05.052 [TRACE] [ng.linktap.protocol.http.WebServerApi] - Validating response from Gateway web UI
00:43:05.057 [TRACE] [ng.linktap.protocol.http.WebServerApi] - Enabling mdns server on gateway
00:43:05.058 [TRACE] [ng.linktap.protocol.http.WebServerApi] - Setting Local HTTP Api on gateway
00:43:05.060 [TRACE] [ng.linktap.protocol.http.WebServerApi] - Found existing HTTP URL Server : http://10.4.40.10:8080/linktap
00:43:05.061 [DEBUG] [linktap.internal.LinkTapBridgeHandler] - 313bbb57-9d10-4e07-ac38-6b3dd13e5a56 = APP BRIDGE -> GW -> Request {"cmd":16,"gw_id":"B17EC52F004B1200"}
00:43:05.062 [TRACE] [ng.linktap.protocol.http.WebServerApi] - API Endpoint: http://10.90.3.2/api.shtml
00:43:05.062 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is queued to be processed to http://10.90.3.2/api.shtml
00:43:05.067 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is beginning to be processed to http://10.90.3.2/api.shtml
00:43:05.068 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request has been reported as successful to http://10.90.3.2/api.shtml
00:43:05.079 [DEBUG] [linktap.internal.LinkTapBridgeHandler] - 313bbb57-9d10-4e07-ac38-6b3dd13e5a56 = APP BRIDGE -> GW -> Response {"cmd":16,"gw_id":"B17EC52F004B1200","ver":"G0609282504271200I","vol_unit":"L","utc_ofs":3600,"end_dev":["D71BC52F004B1200_1","D71BC52F004B1200_2","D71BC52F004B1200_3","D71BC52F004B1200_4"],"dev_name":["Pots & Baskets","ValveLinker_2","Back Garden Right","Back Garden Left"]}

I’ve added it as from looking through the history of jetty client in OpenHab, I can see other people getting weird issues because what sounds like other bindings, potentially using up the pool of resources, or not behaving well. This way it should be clear if the binding cant get the raw communications because something is blocking the requests, (aka some other binding is using everything - in which case its a jetty trace and see what is using all the resources, and then raising a bug report, or if is in fact running the requests we know its communication’s to the GW-01 or the device itself.

If after:

00:43:05.062 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is queued to be processed to http://10.90.3.2/api.shtml

There is a failure after the timeout time instead of:

00:43:05.067 [TRACE] [ng.linktap.protocol.http.WebServerApi] - HTTP Comms request is beginning to be processed to http://10.90.3.2/api.shtml

This would be the scenario where something is using up the common http handler that the binding requires in order to setup the communications. (Just in case the device is being slower although I doubt it in this case - you can try bumping up the gatewayResponseTimeout to say 10 seconds for example under the bridge’s advanced configuration. Higher than this and Im pretty sure you’ll be waiting for some other binding to release the HTTP Comm’s so the binding can use it.

I’ve optimised it where I think it can be so hopefully this will make it into the builds