Binding Modbus 2.5.7. Stops working after unsuccessful read attempt

Add-ons Bindings
, ,
72

People can be remarkably quick on a button. Polling at 200mS only improves your chances a bit. There may also be mechanical switch bounce to deal with here.
You really need a ‘hardware’ solution here - a pulse stretcher technique most likely, though you can implement the effect in logic with PLC type boxes.

That’s just about making sure you capture pushes; you would still need a fast poll for a quick response, but it takes the pressure off a bit.
In your logs you can see your “500” poll is actual around 530mS intervals with the overheads.

1 Like
73

It must been something about modbus then. My house is build with IHC push buttons all around the house. I have no trouble gettting the puls to openhab.
Also my Velbus panels using push buttons are beeing recongnized by openhab all the time.

The issue with push buttons is, when you work with long pressure timings. Then things intend to screw up badly.

74

Openhab 2.5.8 is now released, including the fixes discussed here.

1 Like
75

Sorry about being slow with this but I have had a lot of obligations the last few days.

I set up all the logging as requested and everything seemed to be working. I ran it a good while with no issues. I decided to leave most of the extra logging off for awhile and it was working, was getting events to show a change of state on a couple of inputs. I also have a simple HABPanel set up and I can see when an input changes state. I commented out the “Last_Success” but left the “Last_Error” in my “hvac.items” file and I was still logging events from my inputs when operated so I left it on and went to bed. When I got up after 6-1/2 hours or so I activated my inputs and no events were logged. Without stopping openHAB I opened the the hvac.items file and uncommented the “Last Success” and saved the file. It showed that change in the log and immediately started logging the “Last Success” events and when I operated an input it would show up in the event log and in HABPanel. I thought that was interesting, I never saw any “Last Errors” during this test. I know I should have had all the logging on but wasn’t sure if it would be a problem for my Surface SSD hitting it with so many writes for an extended time. I am inclosing a shot of my log files.

events.log

2020-08-23 21:13:40.403 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:39.886-0500 to 2020-08-23T21:13:40.401-0500
2020-08-23 21:13:40.912 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:40.401-0500 to 2020-08-23T21:13:40.912-0500
2020-08-23 21:13:41.436 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:40.912-0500 to 2020-08-23T21:13:41.434-0500
2020-08-23 21:13:41.965 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:41.434-0500 to 2020-08-23T21:13:41.963-0500
2020-08-23 21:13:42.479 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:41.963-0500 to 2020-08-23T21:13:42.478-0500
2020-08-23 21:13:42.998 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-23T21:13:42.478-0500 to 2020-08-23T21:13:42.997-0500
2020-08-23 21:13:43.521 [temChannelLinkRemovedEvent] - Link 'HVAC_Temp_Last_Success => modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess' has been removed.
2020-08-23 21:14:23.426 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-23 21:14:23.426 [vent.ItemStateChangedEvent] - Turck_i8 changed from OFF to ON
2020-08-23 21:14:24.461 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-23 21:14:24.462 [vent.ItemStateChangedEvent] - Turck_i8 changed from ON to OFF
2020-08-23 21:14:25.494 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32256
2020-08-23 21:14:25.495 [vent.ItemStateChangedEvent] - Turck_i9 changed from OFF to ON
2020-08-23 21:14:26.532 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32256 to -32768
2020-08-23 21:14:26.533 [vent.ItemStateChangedEvent] - Turck_i9 changed from ON to OFF
2020-08-23 21:26:29.610 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-23 21:26:29.611 [vent.ItemStateChangedEvent] - Turck_i8 changed from OFF to ON
2020-08-23 21:26:30.129 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-23 21:26:30.130 [vent.ItemStateChangedEvent] - Turck_i8 changed from ON to OFF
2020-08-23 21:26:31.164 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32256
2020-08-23 21:26:31.164 [vent.ItemStateChangedEvent] - Turck_i9 changed from OFF to ON
2020-08-23 21:26:31.683 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32256 to -32768
2020-08-23 21:26:31.684 [vent.ItemStateChangedEvent] - Turck_i9 changed from ON to OFF
2020-08-23 22:25:09.313 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-23 22:25:09.313 [vent.ItemStateChangedEvent] - Turck_i8 changed from OFF to ON
2020-08-23 22:25:09.831 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-23 22:25:09.831 [vent.ItemStateChangedEvent] - Turck_i8 changed from ON to OFF
2020-08-23 22:25:10.875 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32256
2020-08-23 22:25:10.875 [vent.ItemStateChangedEvent] - Turck_i9 changed from OFF to ON
2020-08-23 22:25:11.395 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32256 to -32768
2020-08-23 22:25:11.397 [vent.ItemStateChangedEvent] - Turck_i9 changed from ON to OFF
2020-08-23 22:38:54.667 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-23 22:38:54.667 [vent.ItemStateChangedEvent] - Turck_i8 changed from OFF to ON
2020-08-23 22:38:55.192 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-23 22:38:55.193 [vent.ItemStateChangedEvent] - Turck_i8 changed from ON to OFF
2020-08-23 22:38:56.222 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32256
2020-08-23 22:38:56.223 [vent.ItemStateChangedEvent] - Turck_i9 changed from OFF to ON
2020-08-23 22:38:57.265 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32256 to -32768
2020-08-23 22:38:57.266 [vent.ItemStateChangedEvent] - Turck_i9 changed from ON to OFF
2020-08-24 05:41:56.010 [.ItemChannelLinkAddedEvent] - Link 'HVAC_Temp_Last_Success-modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess' has been added.
2020-08-24 05:41:56.023 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from NULL to 2020-08-24T05:41:56.020-0500
2020-08-24 05:41:56.091 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:56.020-0500 to 2020-08-24T05:41:56.089-0500
2020-08-24 05:41:56.614 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:56.089-0500 to 2020-08-24T05:41:56.612-0500
2020-08-24 05:41:57.132 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:56.612-0500 to 2020-08-24T05:41:57.129-0500
2020-08-24 05:41:57.652 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:57.129-0500 to 2020-08-24T05:41:57.650-0500
2020-08-24 05:41:58.170 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:57.650-0500 to 2020-08-24T05:41:58.167-0500
2020-08-24 05:41:58.699 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:58.167-0500 to 2020-08-24T05:41:58.697-0500
2020-08-24 05:41:59.232 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:58.697-0500 to 2020-08-24T05:41:59.229-0500
2020-08-24 05:41:59.759 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:59.229-0500 to 2020-08-24T05:41:59.757-0500
2020-08-24 05:42:00.283 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:41:59.757-0500 to 2020-08-24T05:42:00.280-0500
2020-08-24 05:42:00.799 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:00.280-0500 to 2020-08-24T05:42:00.797-0500
2020-08-24 05:42:01.317 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:00.797-0500 to 2020-08-24T05:42:01.317-0500
2020-08-24 05:42:01.844 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:01.317-0500 to 2020-08-24T05:42:01.842-0500
2020-08-24 05:42:02.361 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:01.842-0500 to 2020-08-24T05:42:02.361-0500
2020-08-24 05:42:02.886 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:02.361-0500 to 2020-08-24T05:42:02.884-0500
2020-08-24 05:42:03.412 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:02.884-0500 to 2020-08-24T05:42:03.406-0500
2020-08-24 05:42:03.936 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:03.406-0500 to 2020-08-24T05:42:03.935-0500
2020-08-24 05:42:04.459 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:03.935-0500 to 2020-08-24T05:42:04.457-0500
2020-08-24 05:42:04.989 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:04.457-0500 to 2020-08-24T05:42:04.986-0500
2020-08-24 05:42:05.512 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:04.986-0500 to 2020-08-24T05:42:05.509-0500
2020-08-24 05:42:06.030 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:05.509-0500 to 2020-08-24T05:42:06.029-0500
2020-08-24 05:42:06.555 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:06.029-0500 to 2020-08-24T05:42:06.553-0500
2020-08-24 05:42:07.074 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:06.553-0500 to 2020-08-24T05:42:07.073-0500
2020-08-24 05:42:07.596 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:07.073-0500 to 2020-08-24T05:42:07.595-0500
2020-08-24 05:42:08.114 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:07.595-0500 to 2020-08-24T05:42:08.112-0500
2020-08-24 05:42:08.640 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:08.112-0500 to 2020-08-24T05:42:08.637-0500
2020-08-24 05:42:09.159 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:08.637-0500 to 2020-08-24T05:42:09.157-0500
2020-08-24 05:42:09.675 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:09.157-0500 to 2020-08-24T05:42:09.675-0500
2020-08-24 05:42:10.194 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:09.675-0500 to 2020-08-24T05:42:10.192-0500
2020-08-24 05:42:10.715 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:10.192-0500 to 2020-08-24T05:42:10.714-0500
2020-08-24 05:42:11.228 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:10.714-0500 to 2020-08-24T05:42:11.227-0500
2020-08-24 05:42:11.755 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:11.227-0500 to 2020-08-24T05:42:11.750-0500
2020-08-24 05:42:12.281 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:11.750-0500 to 2020-08-24T05:42:12.279-0500
2020-08-24 05:42:12.798 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:12.279-0500 to 2020-08-24T05:42:12.796-0500
2020-08-24 05:42:13.318 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:12.796-0500 to 2020-08-24T05:42:13.315-0500
2020-08-24 05:42:13.839 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:13.315-0500 to 2020-08-24T05:42:13.836-0500
2020-08-24 05:42:14.361 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:13.836-0500 to 2020-08-24T05:42:14.359-0500
2020-08-24 05:42:14.879 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:14.359-0500 to 2020-08-24T05:42:14.878-0500
2020-08-24 05:42:15.403 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:14.878-0500 to 2020-08-24T05:42:15.402-0500
2020-08-24 05:42:15.925 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:15.402-0500 to 2020-08-24T05:42:15.924-0500
2020-08-24 05:42:16.443 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:15.924-0500 to 2020-08-24T05:42:16.442-0500
2020-08-24 05:42:16.964 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:16.442-0500 to 2020-08-24T05:42:16.962-0500
2020-08-24 05:42:17.476 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:16.962-0500 to 2020-08-24T05:42:17.475-0500
2020-08-24 05:42:17.995 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:17.475-0500 to 2020-08-24T05:42:17.995-0500
2020-08-24 05:42:18.515 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:17.995-0500 to 2020-08-24T05:42:18.514-0500
2020-08-24 05:42:19.025 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:18.514-0500 to 2020-08-24T05:42:19.024-0500
2020-08-24 05:42:19.533 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:19.024-0500 to 2020-08-24T05:42:19.533-0500
2020-08-24 05:42:20.041 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:19.533-0500 to 2020-08-24T05:42:20.040-0500
2020-08-24 05:42:20.565 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:20.040-0500 to 2020-08-24T05:42:20.563-0500
2020-08-24 05:42:21.091 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:20.563-0500 to 2020-08-24T05:42:21.088-0500
2020-08-24 05:42:21.603 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:21.088-0500 to 2020-08-24T05:42:21.601-0500
2020-08-24 05:42:22.126 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:21.601-0500 to 2020-08-24T05:42:22.124-0500
2020-08-24 05:42:22.644 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:22.124-0500 to 2020-08-24T05:42:22.644-0500
2020-08-24 05:42:23.168 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:22.644-0500 to 2020-08-24T05:42:23.167-0500
2020-08-24 05:42:23.692 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:23.167-0500 to 2020-08-24T05:42:23.690-0500
2020-08-24 05:42:24.216 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:23.690-0500 to 2020-08-24T05:42:24.214-0500
2020-08-24 05:42:24.735 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:24.214-0500 to 2020-08-24T05:42:24.733-0500
2020-08-24 05:42:25.254 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:24.733-0500 to 2020-08-24T05:42:25.253-0500
2020-08-24 05:42:25.777 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:25.253-0500 to 2020-08-24T05:42:25.775-0500
2020-08-24 05:42:26.305 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:25.775-0500 to 2020-08-24T05:42:26.304-0500
2020-08-24 05:42:26.816 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:26.304-0500 to 2020-08-24T05:42:26.814-0500
2020-08-24 05:42:27.336 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:26.814-0500 to 2020-08-24T05:42:27.334-0500
2020-08-24 05:42:27.855 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:27.334-0500 to 2020-08-24T05:42:27.853-0500
2020-08-24 05:42:28.376 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-24T05:42:27.853-0500 to 2020-08-24T05:42:28.374-0500
2020-08-24 05:42:28.899 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success 


openhab.log

2020-08-21 06:27:09.738 [INFO ] [ll.impl.action.osgi.CommandExtension] - Unregistering commands for bundle org.apache.karaf.deployer.kar/4.2.7
2020-08-23 20:51:36.183 [INFO ] [port.EventAdminConfigurationNotifier] - Sending Event Admin nofification (configuration successful) to org/ops4j/pax/logging/Configuration
2020-08-23 20:51:36.473 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.shell.commands/4.2.7
2020-08-23 20:51:36.476 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.deployer.kar/4.2.7
2020-08-23 20:51:36.892 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.wrapper.core/4.2.7
2020-08-23 20:51:37.832 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.bundle.core/4.2.7
2020-08-23 20:51:37.874 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.config.core/4.2.7
2020-08-23 20:51:38.165 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.diagnostic.core/4.2.7
2020-08-23 20:51:38.210 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.features.command/4.2.7. Missing dependencies: [org.apache.karaf.features.FeaturesService]
2020-08-23 20:51:38.250 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.http.core/4.2.7. Missing dependencies: [org.apache.karaf.http.core.ProxyService, org.apache.karaf.http.core.ServletService]
2020-08-23 20:51:38.253 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.features.command/4.2.7
2020-08-23 20:51:38.256 [INFO ] [raf.deployer.features.osgi.Activator] - Deployment finished. Registering FeatureDeploymentListener
2020-08-23 20:51:38.305 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.instance.core/4.2.7
2020-08-23 20:51:38.340 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.343 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.345 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.383 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.389 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.392 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.2.7
2020-08-23 20:51:38.443 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.kar.core/4.2.7. Missing dependencies: [org.apache.karaf.kar.KarService]
2020-08-23 20:51:38.465 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.log.core/4.2.7. Missing dependencies: [org.apache.karaf.log.core.LogEventFormatter, org.apache.karaf.log.core.LogService]
2020-08-23 20:51:38.481 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.package.core/4.2.7
2020-08-23 20:51:38.493 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.scr.state/4.2.7
2020-08-23 20:51:38.517 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.service.core/4.2.7
2020-08-23 20:51:38.524 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.log.core/4.2.7
2020-08-23 20:51:38.537 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.kar.core/4.2.7
2020-08-23 20:51:38.666 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.shell.ssh/4.2.7. Missing dependencies: [org.apache.sshd.server.SshServer]
2020-08-23 20:51:38.686 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.system.core/4.2.7
2020-08-23 20:51:38.837 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Examining bundle for SPI provider: org.eclipse.jetty.http
2020-08-23 20:51:38.842 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://80.fwk418958713/META-INF/services/org.eclipse.jetty.http.HttpFieldPreEncoder
2020-08-23 20:51:38.953 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.http.Http1FieldPreEncoder
2020-08-23 20:51:38.954 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.http.HttpFieldPreEncoder}={serviceloader.mediator=39, service.id=108, service.bundleid=80, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.http.Http1FieldPreEncoder}
2020-08-23 20:51:38.965 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.http.HttpFieldPreEncoder in bundle org.eclipse.jetty.http
2020-08-23 20:51:38.981 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Examining bundle for SPI provider: org.eclipse.jetty.websocket.common
2020-08-23 20:51:38.982 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://98.fwk418958713/META-INF/services/org.eclipse.jetty.websocket.api.extensions.Extension
2020-08-23 20:51:39.038 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.common.extensions.identity.IdentityExtension
2020-08-23 20:51:39.040 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.websocket.api.extensions.Extension}={serviceloader.mediator=39, service.id=109, service.bundleid=98, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.common.extensions.identity.IdentityExtension}
2020-08-23 20:51:39.041 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.websocket.api.extensions.Extension in bundle org.eclipse.jetty.websocket.common
2020-08-23 20:51:39.043 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.common.extensions.fragment.FragmentExtension
2020-08-23 20:51:39.044 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.websocket.api.extensions.Extension}={serviceloader.mediator=39, service.id=110, service.bundleid=98, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.common.extensions.fragment.FragmentExtension}
2020-08-23 20:51:39.045 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.websocket.api.extensions.Extension in bundle org.eclipse.jetty.websocket.common
2020-08-23 20:51:39.055 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension
2020-08-23 20:51:39.060 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.websocket.api.extensions.Extension}={serviceloader.mediator=39, service.id=111, service.bundleid=98, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension}
2020-08-23 20:51:39.061 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.websocket.api.extensions.Extension in bundle org.eclipse.jetty.websocket.common
2020-08-23 20:51:39.062 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.common.extensions.compress.DeflateFrameExtension
2020-08-23 20:51:39.064 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.websocket.api.extensions.Extension}={serviceloader.mediator=39, service.id=112, service.bundleid=98, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.common.extensions.compress.DeflateFrameExtension}
2020-08-23 20:51:39.066 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.websocket.api.extensions.Extension in bundle org.eclipse.jetty.websocket.common
2020-08-23 20:51:39.067 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.common.extensions.compress.XWebkitDeflateFrameExtension
2020-08-23 20:51:39.072 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {org.eclipse.jetty.websocket.api.extensions.Extension}={serviceloader.mediator=39, service.id=113, service.bundleid=98, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.common.extensions.compress.XWebkitDeflateFrameExtension}
2020-08-23 20:51:39.074 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: org.eclipse.jetty.websocket.api.extensions.Extension in bundle org.eclipse.jetty.websocket.common
2020-08-23 20:51:39.079 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Examining bundle for SPI provider: org.eclipse.jetty.websocket.javax.websocket
2020-08-23 20:51:39.082 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://99.fwk418958713/META-INF/services/javax.websocket.ContainerProvider
2020-08-23 20:51:39.085 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.jsr356.JettyClientContainerProvider
2020-08-23 20:51:39.086 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {javax.websocket.ContainerProvider}={serviceloader.mediator=39, service.id=114, service.bundleid=99, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.jsr356.JettyClientContainerProvider}
2020-08-23 20:51:39.087 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: javax.websocket.ContainerProvider in bundle org.eclipse.jetty.websocket.javax.websocket
2020-08-23 20:51:39.089 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Examining bundle for SPI provider: org.eclipse.jetty.websocket.javax.websocket.server
2020-08-23 20:51:39.090 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://100.fwk418958713/META-INF/services/javax.servlet.ServletContainerInitializer
2020-08-23 20:51:39.092 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.jsr356.server.deploy.WebSocketServerContainerInitializer
2020-08-23 20:51:39.093 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {javax.servlet.ServletContainerInitializer}={serviceloader.mediator=39, service.id=115, service.bundleid=100, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.jsr356.server.deploy.WebSocketServerContainerInitializer}
2020-08-23 20:51:39.094 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: javax.servlet.ServletContainerInitializer in bundle org.eclipse.jetty.websocket.javax.websocket.server
2020-08-23 20:51:39.094 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://100.fwk418958713/META-INF/services/javax.websocket.server.ServerEndpointConfig$Configurator
2020-08-23 20:51:39.096 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.jsr356.server.ContainerDefaultConfigurator
2020-08-23 20:51:39.097 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {javax.websocket.server.ServerEndpointConfig$Configurator}={serviceloader.mediator=39, service.id=116, service.bundleid=100, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.jsr356.server.ContainerDefaultConfigurator}
2020-08-23 20:51:39.097 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: javax.websocket.server.ServerEndpointConfig$Configurator in bundle org.eclipse.jetty.websocket.javax.websocket.server
2020-08-23 20:51:39.099 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Examining bundle for SPI provider: org.eclipse.jetty.websocket.server
2020-08-23 20:51:39.099 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Found SPI resource: bundleentry://101.fwk418958713/META-INF/services/javax.servlet.ServletContainerInitializer
2020-08-23 20:51:39.101 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Loaded SPI provider: class org.eclipse.jetty.websocket.server.NativeWebSocketServletContainerInitializer
2020-08-23 20:51:39.102 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered service: {javax.servlet.ServletContainerInitializer}={serviceloader.mediator=39, service.id=117, service.bundleid=101, service.scope=bundle, .org.apache.aries.spifly.provider.implclass=org.eclipse.jetty.websocket.server.NativeWebSocketServletContainerInitializer}
2020-08-23 20:51:39.102 [INFO ] [rg.apache.aries.spifly.BaseActivator] - Registered provider: javax.servlet.ServletContainerInitializer in bundle org.eclipse.jetty.websocket.server
2020-08-23 20:51:39.179 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.shell.ssh/4.2.7
2020-08-23 20:51:39.247 [INFO ] [org.eclipse.jetty.util.log          ] - Logging initialized @5891ms to org.eclipse.jetty.util.log.Slf4jLog
2020-08-23 20:51:39.281 [INFO ] [j.pax.web.service.internal.Activator] - EventAdmin support enabled, servlet events will be postet to topics.
2020-08-23 20:51:39.283 [INFO ] [j.pax.web.service.internal.Activator] - LogService support enabled, log events will be created.
2020-08-23 20:51:39.291 [INFO ] [j.pax.web.service.internal.Activator] - Pax Web started
2020-08-23 20:51:39.650 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.event/4.2.7
2020-08-23 20:51:40.098 [INFO ] [org.eclipse.jetty.util.TypeUtil     ] - JVM Runtime does not support Modules
2020-08-23 20:51:40.162 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '31.581896,-94.465492'.
2020-08-23 20:51:40.207 [INFO ] [rvice.jetty.internal.JettyServerImpl] - Pax Web available at [0.0.0.0]:[8443]
2020-08-23 20:51:40.223 [INFO ] [vice.jetty.internal.JettyFactoryImpl] - No ALPN class available
2020-08-23 20:51:40.223 [INFO ] [vice.jetty.internal.JettyFactoryImpl] - HTTP/2 not available, creating standard ServerConnector for Http
2020-08-23 20:51:40.225 [INFO ] [rvice.jetty.internal.JettyServerImpl] - Pax Web available at [0.0.0.0]:[8080]
2020-08-23 20:51:40.230 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.apache.karaf.http.core_4.2.7 [53]] to http service
2020-08-23 20:51:40.265 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.ops4j.pax.web.pax-web-extender-whiteboard_7.2.11 [193]] to http service
2020-08-23 20:51:40.273 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19]] to http service
2020-08-23 20:51:40.276 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.http.core/4.2.7
2020-08-23 20:51:41.041 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.audio_2.5.0 [134]] to http service
2020-08-23 20:51:41.055 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:41.094 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.audio_2.5.0 [134], contextID=default], with context-name: 
2020-08-23 20:51:41.108 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:41.174 [INFO ] [org.eclipse.jetty.server.session    ] - DefaultSessionIdManager workerName=node0
2020-08-23 20:51:41.175 [INFO ] [org.eclipse.jetty.server.session    ] - No SessionScavenger set, using defaults
2020-08-23 20:51:41.178 [INFO ] [org.eclipse.jetty.server.session    ] - node0 Scavenging every 600000ms
2020-08-23 20:51:41.191 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.audio_2.5.0 [134], contextID=default]}
2020-08-23 20:51:41.202 [INFO ] [org.eclipse.jetty.server.Server     ] - jetty-9.4.20.v20190813; built: 2019-08-13T21:28:18.144Z; git: 84700530e645e812b336747464d6fbbf370c9a20; jvm 1.8.0_252-b14
2020-08-23 20:51:41.226 [INFO ] [.jetty.server.handler.ContextHandler] - Started o.e.j.s.h.ContextHandler@743f1b5f{/static,null,AVAILABLE}
2020-08-23 20:51:41.251 [INFO ] [pse.jetty.util.ssl.SslContextFactory] - x509=X509@39995ada(mykey,h=[openhab.org],w=[]) for Server@f7750e9[provider=null,keyStore=file:///C:/openhab2/userdata/etc/keystore,trustStore=file:///C:/openhab2/userdata/etc/keystore]
2020-08-23 20:51:41.310 [INFO ] [lipse.jetty.server.AbstractConnector] - Started 0.0.0.0:8443@55979a4{SSL,[ssl, http/1.1]}{0.0.0.0:8443}
2020-08-23 20:51:41.316 [INFO ] [lipse.jetty.server.AbstractConnector] - Started default@216627c7{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
2020-08-23 20:51:41.317 [INFO ] [org.eclipse.jetty.server.Server     ] - Started @7961ms
2020-08-23 20:51:41.764 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:41.765 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19], contextID=default], with context-name: 
2020-08-23 20:51:41.766 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:41.774 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19], contextID=default]}
2020-08-23 20:51:41.811 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.io.http_2.5.0 [147]] to http service
2020-08-23 20:51:44.013 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.openhab.core.karaf/2.5.0
2020-08-23 20:51:45.204 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hvac.items'
2020-08-23 20:51:45.659 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'modbus.things'
2020-08-23 20:51:45.735 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Using default implementation for ThreadExecutor
2020-08-23 20:51:45.752 [INFO ] [rg.quartz.core.SchedulerSignalerImpl] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2020-08-23 20:51:45.752 [INFO ] [org.quartz.core.QuartzScheduler     ] - Quartz Scheduler v.2.2.1 created.
2020-08-23 20:51:45.753 [INFO ] [org.quartz.simpl.RAMJobStore        ] - RAMJobStore initialized.
2020-08-23 20:51:45.754 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler meta-data: Quartz Scheduler (v2.2.1) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2020-08-23 20:51:45.755 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: 'C:\openhab2\runtime/etc/quartz.properties'
2020-08-23 20:51:45.755 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Quartz scheduler version: 2.2.1
2020-08-23 20:51:45.756 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
2020-08-23 20:51:46.777 [INFO ] [org.quartz.core.QuartzScheduler     ] - JobFactory set to: org.eclipse.smarthome.model.rule.runtime.internal.engine.GuiceAwareJobFactory@267cf7e2
2020-08-23 20:51:46.778 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED paused.
2020-08-23 20:51:46.898 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-08-23 20:51:47.336 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.ui_2.5.0 [188]] to http service
2020-08-23 20:51:47.341 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:47.342 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.ui_2.5.0 [188], contextID=custom], with context-name: 
2020-08-23 20:51:47.344 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:47.387 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.ui_2.5.0 [188], contextID=custom]}
2020-08-23 20:51:47.448 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:47.449 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.ui_2.5.0 [188], contextID=default], with context-name: 
2020-08-23 20:51:47.450 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:47.515 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.ui_2.5.0 [188], contextID=default]}
2020-08-23 20:51:47.528 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.ui.icon_2.5.0 [189]] to http service
2020-08-23 20:51:47.531 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:47.532 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.ui.icon_2.5.0 [189], contextID=default], with context-name: 
2020-08-23 20:51:47.533 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:47.545 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.ui.icon_2.5.0 [189], contextID=default]}
2020-08-23 20:51:47.592 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.dashboard_2.5.6 [191]] to http service
2020-08-23 20:51:47.603 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:47.605 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.5.6 [191], contextID=default], with context-name: 
2020-08-23 20:51:47.606 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:47.629 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.5.6 [191], contextID=default]}
2020-08-23 20:51:47.633 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:47.639 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.5.6 [191], contextID=custom], with context-name: 
2020-08-23 20:51:47.642 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:47.666 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.5.6 [191], contextID=custom]}
2020-08-23 20:51:47.669 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.43:8080
2020-08-23 20:51:47.669 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.43:8443
2020-08-23 20:51:47.717 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-08-23 20:51:48.253 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.basic_2.5.7 [216]] to http service
2020-08-23 20:51:48.262 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:48.263 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.7 [216], contextID=custom], with context-name: 
2020-08-23 20:51:48.264 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:48.313 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.7 [216], contextID=custom]}
2020-08-23 20:51:48.324 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:48.325 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.7 [216], contextID=custom], with context-name: 
2020-08-23 20:51:48.334 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:48.370 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.7 [216], contextID=custom]}
2020-08-23 20:51:48.450 [INFO ] [d.internal.element.ServletWebElement] - Ignoring servlet [362] without valid alias or url patterns property.
2020-08-23 20:51:48.524 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.habpanel_2.5.7 [217]] to http service
2020-08-23 20:51:48.539 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:48.540 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.5.7 [217], contextID=default], with context-name: 
2020-08-23 20:51:48.541 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:48.577 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.5.7 [217], contextID=default]}
2020-08-23 20:51:48.579 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-08-23 20:51:48.594 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.homebuilder_2.5.7 [218]] to http service
2020-08-23 20:51:48.610 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:48.613 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.homebuilder_2.5.7 [218], contextID=default], with context-name: 
2020-08-23 20:51:48.614 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:48.650 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.homebuilder_2.5.7 [218], contextID=default]}
2020-08-23 20:51:48.652 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2020-08-23 20:51:48.727 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.paper_2.5.7 [220]] to http service
2020-08-23 20:51:48.731 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:48.732 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.paper_2.5.7 [220], contextID=custom], with context-name: 
2020-08-23 20:51:48.734 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:48.768 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.paper_2.5.7 [220], contextID=custom]}
2020-08-23 20:51:48.769 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-08-23 20:51:50.784 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.boot_2.5.0 [137]] to http service
2020-08-23 20:51:50.788 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2020-08-23 20:51:50.788 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.boot_2.5.0 [137], contextID=default], with context-name: 
2020-08-23 20:51:50.789 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering JasperInitializer
2020-08-23 20:51:50.809 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.boot_2.5.0 [137], contextID=default]}
2020-08-23 20:51:51.790 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
2020-08-23 21:13:43.498 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'hvac.items'
2020-08-24 05:41:56.000 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'hvac.items'
2020-08-24 05:42:01.012 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.


hvac.items

Number HVAC_Temp "Temp [%d]" { channel="modbus:data:HVAC:hvacpoll:reg32768:number" }
Switch Turck_i0 "i0 [%s]" { channel="modbus:data:HVAC:hvacpoll:di0:switch" }
Switch Turck_i1 "i1 [%s]" { channel="modbus:data:HVAC:hvacpoll:di1:switch" }
Switch Turck_i2 "i2 [%s]" { channel="modbus:data:HVAC:hvacpoll:di2:switch" }
Switch Turck_i3 "i3 [%s]" { channel="modbus:data:HVAC:hvacpoll:di3:switch" }
Switch Turck_i4 "i4 [%s]" { channel="modbus:data:HVAC:hvacpoll:di4:switch" }
Switch Turck_i5 "i5 [%s]" { channel="modbus:data:HVAC:hvacpoll:di5:switch" }
Switch Turck_i6 "i6 [%s]" { channel="modbus:data:HVAC:hvacpoll:di6:switch" }
Switch Turck_i7 "i7 [%s]" { channel="modbus:data:HVAC:hvacpoll:di7:switch" }
Switch Turck_i8 "i8 [%s]" { channel="modbus:data:HVAC:hvacpoll:di8:switch" }
Switch Turck_i9 "i9 [%s]" { channel="modbus:data:HVAC:hvacpoll:di9:switch" }
Switch Turck_i10 "i10 [%s]" { channel="modbus:data:HVAC:hvacpoll:di10:switch" }
Switch Turck_i11 "i11 [%s]" { channel="modbus:data:HVAC:hvacpoll:di11:switch" }
Switch Turck_i12 "i12 [%s]" { channel="modbus:data:HVAC:hvacpoll:di12:switch" }
Switch Turck_i13 "i13 [%s]" { channel="modbus:data:HVAC:hvacpoll:di13:switch" }
Switch Turck_i14 "i14 [%s]" { channel="modbus:data:HVAC:hvacpoll:di14:switch" }
Switch Turck_i15 "i15 [%s]" { channel="modbus:data:HVAC:hvacpoll:di15:switch" }
DateTime HVAC_Temp_Last_Success  "Temp last ok [%1$tA, %1$td.%1$tm.%1$tY %1$tH:%1$tM:%1$tS" { channel="modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess" }
DateTime HVAC_Temp_Last_Error "Temp last err [%1$tA, %1$td.%1$tm.%1$tY %1$tH:%1$tM:%1$tS" { channel="modbus:data:HVAC:hvacpoll:reg32768:lastReadError" }
76

You Surface shouldn´t suffer from any problems. If you use the standard log settings, it will create a maximum of 10x 10Mb file size and overwrite the oldest.

77

@bhall sorry to say this but it’s impossible to get to the root of the issue with this little information. To help you, I would need verbose logs from the time it works, and when it starts to not work.

I suggest considering to update your openHAB and binding to stable 2.5.8, now that it is out. This also introduces some small logging fixes that are needed to diagnose traffic using DEBUG level.

You can reduce the amount of logging by

  • lowering poll rate to 30 s
  • simplifying your item configuration, leave only Number HVAC_Temp, DateTime HVAC_Temp_Last_Success and DateTime HVAC_Temp_Last_Error
  • Simplify your things, remove diXX things and leave only the tcp, poller and data reg32768
  • Setting log level to DEBUG instead of TRACE: log:set DEBUG org.openhab.io.transport.modbus and log:set DEBUG org.openhab.binding.modbus.

Let it run as long as needed, so it eventually stops working.

You should see log lines like the below Thing modbus:poller:fc8f3903 received response ...

20:52:32.321 [DEBUG] [dbus.handler.ModbusPollerThingHandler] - Thing modbus:poller:fc8f3903 received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@412a0b1a[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=5,maxTries=3], registers = ModbusRegisterArrayImpl(00 00 00 00 00 00 00 00 00 00)))
78

Per your recommendation I will do the upgrade as soon as I can and can leave it going at the 30 sec interval.

Do you think 60 seconds would be too long of an interval?

79

Thanks @BHall. Make sure you remove the snapshot versions from the addons folder.

60 seconds works as well in the sense that logs would tell whether the binding itself is working as expected . I hope that whatever you are experiencing would still happen with the lower poll rate.

80

I did another clean install and went with the stable 2.5.8 as you suggested, then went into the PaperUI and installed the Modbus binding. I then exited the PaperUI and copied my item and thing files setting them up in a minimal way. I let it run overnight, I think around 7 hours. Got up this morning and activated an input before doing anything else or looking at logs. The change showed up in the event log and it appears to have run all night, apparently without issues. I am including a sample of log files.

This is the longest success so far.

events.log

2020-08-25 05:42:38.159 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:42:08.125-0500 to 2020-08-25T05:42:38.158-0500
2020-08-25 05:43:08.173 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:42:38.158-0500 to 2020-08-25T05:43:08.172-0500
2020-08-25 05:43:38.197 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:43:08.172-0500 to 2020-08-25T05:43:38.195-0500
2020-08-25 05:44:08.215 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:43:38.195-0500 to 2020-08-25T05:44:08.213-0500
2020-08-25 05:44:38.233 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:44:08.213-0500 to 2020-08-25T05:44:38.231-0500
2020-08-25 05:45:08.262 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:44:38.231-0500 to 2020-08-25T05:45:08.260-0500
2020-08-25 05:45:38.281 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-25 05:45:38.282 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:45:08.260-0500 to 2020-08-25T05:45:38.280-0500
2020-08-25 05:46:08.297 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-25 05:46:08.297 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:45:38.280-0500 to 2020-08-25T05:46:08.296-0500
2020-08-25 05:46:38.324 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:46:08.296-0500 to 2020-08-25T05:46:38.321-0500
2020-08-25 05:47:08.345 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:46:38.321-0500 to 2020-08-25T05:47:08.343-0500
2020-08-25 05:47:38.363 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:47:08.343-0500 to 2020-08-25T05:47:38.361-0500
2020-08-25 05:48:08.381 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:47:38.361-0500 to 2020-08-25T05:48:08.379-0500
2020-08-25 05:48:38.397 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:48:08.379-0500 to 2020-08-25T05:48:38.395-0500
2020-08-25 05:49:08.411 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:48:38.395-0500 to 2020-08-25T05:49:08.409-0500
2020-08-25 05:49:38.428 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:49:08.409-0500 to 2020-08-25T05:49:38.427-0500
2020-08-25 05:50:08.443 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:49:38.427-0500 to 2020-08-25T05:50:08.441-0500
2020-08-25 05:50:38.472 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:50:08.441-0500 to 2020-08-25T05:50:38.469-0500
2020-08-25 05:51:08.501 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:50:38.469-0500 to 2020-08-25T05:51:08.499-0500
2020-08-25 05:51:38.527 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:51:08.499-0500 to 2020-08-25T05:51:38.524-0500
2020-08-25 05:52:08.542 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32768 to -32512
2020-08-25 05:52:08.542 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:51:38.524-0500 to 2020-08-25T05:52:08.540-0500
2020-08-25 05:52:38.568 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:52:08.540-0500 to 2020-08-25T05:52:38.566-0500
2020-08-25 05:53:08.587 [vent.ItemStateChangedEvent] - HVAC_Temp changed from -32512 to -32768
2020-08-25 05:53:08.588 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:52:38.566-0500 to 2020-08-25T05:53:08.585-0500
2020-08-25 05:53:38.611 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:53:08.585-0500 to 2020-08-25T05:53:38.608-0500
2020-08-25 05:54:08.631 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:53:38.608-0500 to 2020-08-25T05:54:08.630-0500
2020-08-25 05:54:38.661 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:54:08.630-0500 to 2020-08-25T05:54:38.658-0500
2020-08-25 05:55:08.686 [vent.ItemStateChangedEvent] - HVAC_Temp_Last_Success changed from 2020-08-25T05:54:38.658-0500 to 2020-08-25T05:55:08.685-0500


openhab.log

2020-08-25 05:49:08.412 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 12 ms, connection: 5, transaction=4, callback=3} [operation ID 119856bd-d0f5-44dc-b004-61e181195040]
2020-08-25 05:49:08.412 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352548412. Was started at millis: 1598352548399 (=duration of 13 millis)
2020-08-25 05:49:15.933 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:49:38.419 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352578419
2020-08-25 05:49:38.420 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:49:38.426 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:49:38.427 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:49:38.427-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:49:38.428 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 8 ms, connection: 4, transaction=2, callback=2} [operation ID c95da290-c2e0-4e81-8ad4-ed35bb63546d]
2020-08-25 05:49:38.428 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352578428. Was started at millis: 1598352578419 (=duration of 9 millis)
2020-08-25 05:49:44.356 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:50:05.026 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:50:05.026 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:50:05.027 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:50:05.027 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:50:05.028 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:50:05.028 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:50:08.432 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352608432
2020-08-25 05:50:08.433 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:50:08.441 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:50:08.442 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:50:08.441-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:50:08.444 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 11 ms, connection: 5, transaction=3, callback=3} [operation ID d5a3ddd3-ba9f-4d56-80d4-ad819f88d4a0]
2020-08-25 05:50:08.444 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352608444. Was started at millis: 1598352608432 (=duration of 12 millis)
2020-08-25 05:50:12.396 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:50:35.757 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:50:38.458 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352638458
2020-08-25 05:50:38.459 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:50:38.468 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:50:38.470 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:50:38.469-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:50:38.472 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 13 ms, connection: 6, transaction=4, callback=3} [operation ID bae506c0-35d3-489f-9c00-c1b5ef01be9d]
2020-08-25 05:50:38.474 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352638474. Was started at millis: 1598352638458 (=duration of 16 millis)
2020-08-25 05:50:59.768 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:51:05.038 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:51:05.038 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:51:05.039 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:51:05.039 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:51:05.039 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:51:05.040 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:51:08.490 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352668490
2020-08-25 05:51:08.491 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:51:08.499 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:51:08.500 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:51:08.499-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:51:08.501 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 11 ms, connection: 5, transaction=3, callback=3} [operation ID ce204d43-13a3-47f3-95f6-fce5193cbe5f]
2020-08-25 05:51:08.501 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352668501. Was started at millis: 1598352668490 (=duration of 11 millis)
2020-08-25 05:51:24.265 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:51:38.512 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352698512
2020-08-25 05:51:38.513 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:51:38.523 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:51:38.525 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:51:38.524-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:51:38.527 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 14 ms, connection: 7, transaction=3, callback=3} [operation ID 71ae18c5-bcf8-4292-a1c0-1b350a6189d5]
2020-08-25 05:51:38.528 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352698528. Was started at millis: 1598352698512 (=duration of 16 millis)
2020-08-25 05:51:49.663 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:52:05.051 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:52:05.051 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:52:05.052 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:52:05.052 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:52:05.052 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:52:05.053 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:52:08.531 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352728531
2020-08-25 05:52:08.532 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:52:08.540 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(81 00)))
2020-08-25 05:52:08.541 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32512, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:52:08.540-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32512 and boolValue=true. Registers ModbusRegisterArrayImpl(81 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:52:08.543 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 11 ms, connection: 4, transaction=4, callback=3} [operation ID f31894cb-4201-4b36-bcbc-93eb51b9119d]
2020-08-25 05:52:08.543 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352728543. Was started at millis: 1598352728531 (=duration of 12 millis)
2020-08-25 05:52:14.340 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:52:38.557 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352758557
2020-08-25 05:52:38.558 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:52:38.565 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(81 00)))
2020-08-25 05:52:38.567 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32512, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:52:38.566-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32512 and boolValue=true. Registers ModbusRegisterArrayImpl(81 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:52:38.569 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 11 ms, connection: 4, transaction=4, callback=3} [operation ID e94afb93-eae8-449d-9606-983d3ec2adbe]
2020-08-25 05:52:38.569 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352758569. Was started at millis: 1598352758557 (=duration of 12 millis)
2020-08-25 05:52:42.832 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:53:05.067 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:53:08.574 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352788574
2020-08-25 05:53:08.575 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:53:08.584 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:53:08.586 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:53:08.585-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:53:08.588 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 13 ms, connection: 5, transaction=4, callback=4} [operation ID 14106b6a-b329-4e9e-a4b5-72af1c3c4533]
2020-08-25 05:53:08.588 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352788588. Was started at millis: 1598352788574 (=duration of 14 millis)
2020-08-25 05:53:09.833 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:53:35.230 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:53:38.596 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352818596
2020-08-25 05:53:38.597 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:53:38.607 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:53:38.609 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:53:38.608-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:53:38.611 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 14 ms, connection: 6, transaction=3, callback=5} [operation ID 30e58def-40a2-423d-a7e2-f8d21cff3cd6]
2020-08-25 05:53:38.612 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352818612. Was started at millis: 1598352818596 (=duration of 16 millis)
2020-08-25 05:53:58.424 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:54:05.070 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:54:05.070 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:54:05.071 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:54:05.071 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:54:05.071 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:54:05.071 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:54:08.623 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352848623
2020-08-25 05:54:08.623 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:54:08.630 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:54:08.631 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:54:08.630-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:54:08.631 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 8 ms, connection: 4, transaction=3, callback=1} [operation ID 58ca41b4-8af3-421b-917f-3bbb2df9adec]
2020-08-25 05:54:08.632 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352848632. Was started at millis: 1598352848623 (=duration of 9 millis)
2020-08-25 05:54:28.401 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:54:38.646 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352878646
2020-08-25 05:54:38.647 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:54:38.657 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:54:38.659 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:54:38.658-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:54:38.661 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 14 ms, connection: 7, transaction=3, callback=4} [operation ID c9318198-d321-40b9-b759-b26b4a676a7d]
2020-08-25 05:54:38.662 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352878662. Was started at millis: 1598352878646 (=duration of 16 millis)
2020-08-25 05:54:52.761 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:55:05.080 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.openhab.addons)
2020-08-25 05:55:05.081 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/2.5.0
2020-08-25 05:55:05.081 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:55:05.082 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:55:05.082 [DEBUG] [org.apache.felix.configadmin        ] - getConfiguration(pid=org.ops4j.pax.url.mvn, location=null)
2020-08-25 05:55:05.083 [DEBUG] [org.apache.felix.configadmin        ] - Found cached configuration org.ops4j.pax.url.mvn bound to ?
2020-08-25 05:55:08.678 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b]. Current millis: 1598352908678
2020-08-25 05:55:08.678 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-08-25 05:55:08.685 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:HVAC:hvacpoll received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3], registers = ModbusRegisterArrayImpl(80 00)))
2020-08-25 05:55:08.686 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:HVAC:hvacpoll:reg32768 channels updated: {modbus:data:HVAC:hvacpoll:reg32768:number=-32768, modbus:data:HVAC:hvacpoll:reg32768:lastReadSuccess=2020-08-25T05:55:08.685-0500}. readValueType=int16, readIndex=Optional[32768], readSubIndex(or 0)=0, extractIndex=0 -> numeric value -32768 and boolValue=true. Registers ModbusRegisterArrayImpl(80 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3]
2020-08-25 05:55:08.687 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 8 ms, connection: 4, transaction=2, callback=2} [operation ID 64e9bda7-7e35-464b-9955-c8e4d4d1b523]
2020-08-25 05:55:08.687 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (30000ms) poll task BasicPollTask@4e64568b[request=ModbusPollerThingHandler.ModbusPollerReadRequest@456ecc78[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@50929ac[address=192.168.1.111,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@5f4fb53b] finished at 1598352908687. Was started at millis: 1598352908678 (=duration of 9 millis)
2020-08-25 05:55:19.118 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2020-08-25 05:55:28.346 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'logout'
2020-08-25 05:55:28.353 [INFO ] [raf.shell.commands.impl.LogoutAction] - Disconnecting from current session...
1 Like
81

Update:

I ran the Modbus trial again overnight last night with the only change being going from reading once every 30 seconds to once per second.

Everything was still working this morning and I still have not noticed any errors.

I have not done any more today, trying to prepare and waiting to see what hurricane Laura does to us.

82

@ssalonen,

I ran the previous test overnight last night with the extra logging as before and it ran all night, it would still log changes in the register this morning and I did not notice any errors. The refresh was set for 1000 ms.

This morning, without shutting down openhab, I changed the refresh to 250 ms and it has ran since then and will still log changes in the register and I haven’t noticed any errors, repeatedly logging the HVAC_Temp_Last_Success message in the event log.

The purpose of all of this was to produce some errors in the logs that I could send but everything seems to run good when the logging is in place.

I guess I will try again later this evening with some of the extra logging removed and see what happens. The last time I tried running it without the extra logging it wasn’t long before it quit logging changes in the register.

It almost seems like when you keep it constantly busy everything works but when the extra logging is removed it goes back to not logging register changes for very long.

For what it’s worth, all openhab is currently doing is the reading and logging of the single Modbus register. I have held off on doing anything else with openhab until I could get this issue resolved.

Maybe I could turn the extra stuff off one item at a time and see if/when it quits again. I wouldn’t mind some logging being in place all the time if that would keep it working, but it seems like that should be unnecessary and I am using solid state drives and understand there is limit on total writes before the drive expires although that limit is probably a lot.

It seems to work very well except for this one issue.

I may be doing something very stupid here but I don’t know what it is. I feel very bad about wasting your time and the time of others that have tried to help. I have been reading a lot of posts in another thread where there was a lot of heated arguments back and forth over time wasted fooling with inexperienced users and I really don’t want to be one of those they are talking about.

I will proceed with what I mentioned unless you might have a better idea.

Thanks again!

83

Thanks @BHall for troubleshooting this

I am quite curious to get bottom of this so appreciate the help.

For what it’s worth, we have other user reporting similar behavior at Modbus stops without any errors so maybe there is something in the code that stops working.

84

@ssalonen,

Everything continued to work with the logging enabled until late last night.

I then issued the following commands:
openhab> log:set INFO org.openhab.io.transport.modbus
openhab> log:set INFO org.openhab.binding.modbus

This was the final entry in "openhab.log" since last night when I issued the last command changing from DEBUG to INFO.

2020-08-30 22:57:48.040 [INFO ] [port.EventAdminConfigurationNotifier] - Sending Event Admin nofification (configuration successful) to org/ops4j/pax/logging/Configuration

Timeline of some of my final activity in “events.log” on 8/30/2020:

The following “register change logged in events log” were the result of operating an input:
22:54 - register change logged in events log
22:59 - register change logged in events log
23:00 - register change logged in events log
23:01 - register change logged in events log
23:03 - register change logged in events log

The very last entry in “events.log” - Up until this point entries in the log were normal and regular:
23:26 - final entry in “events.log” - “HVAC_Temp_Last_Success”

As I mentioned before, not long after changing from DEBUG to INFO I stop getting entries in the events log. This appears to be a repeatable thing. I can repeat this test again tonight if you need me to.

I hope this information might be of some help.

85

I’m also affected by this problem. It started after the update to 2.5.7. I’m om 2.5.8 now, but the problem is still here.

The binding works for max. 24 hours and then just stops. Since I set the log level to DEBUG I no longer see an error message, which was there with the default logging settings (Will see if I can find it somewhere). Now it is just this:

2020-08-30 22:06:51.592 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_AC_VAR_SF channels updated: {modbus:data:SE7K:Registers:I_AC_VAR_SF:number=0}. readValueType=int16, readIndex=Optional[90], readSubIndex(or 0)=0, extractIndex=21 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.593 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_AC_PF channels updated: {modbus:data:SE7K:Registers:I_AC_PF:number=0}. readValueType=int16, readIndex=Optional[91], readSubIndex(or 0)=0, extractIndex=22 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.593 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_AC_PF_SF channels updated: {modbus:data:SE7K:Registers:I_AC_PF_SF:number=0}. readValueType=int16, readIndex=Optional[92], readSubIndex(or 0)=0, extractIndex=23 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.593 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_AC_Energy_WH channels updated: {modbus:data:SE7K:Registers:I_AC_Energy_WH:number=2094373}. readValueType=int32, readIndex=Optional[93], readSubIndex(or 0)=0, extractIndex=24 -> numeric value 2094373 and boolValue=true. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.593 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_AC_Energy_WH_SF channels updated: {modbus:data:SE7K:Registers:I_AC_Energy_WH_SF:number=0}. readValueType=uint16, readIndex=Optional[95], readSubIndex(or 0)=0, extractIndex=26 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.593 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Current channels updated: {modbus:data:SE7K:Registers:I_DC_Current:number=0}. readValueType=uint16, readIndex=Optional[96], readSubIndex(or 0)=0, extractIndex=27 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Current_SF channels updated: {modbus:data:SE7K:Registers:I_DC_Current_SF:number=0}. readValueType=int16, readIndex=Optional[97], readSubIndex(or 0)=0, extractIndex=28 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Voltage channels updated: {modbus:data:SE7K:Registers:I_DC_Voltage:number=0}. readValueType=uint16, readIndex=Optional[98], readSubIndex(or 0)=0, extractIndex=29 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Voltage_SF channels updated: {modbus:data:SE7K:Registers:I_DC_Voltage_SF:number=-1}. readValueType=int16, readIndex=Optional[99], readSubIndex(or 0)=0, extractIndex=30 -> numeric value -1 and boolValue=true. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Power channels updated: {modbus:data:SE7K:Registers:I_DC_Power:number=0}. readValueType=int16, readIndex=Optional[100], readSubIndex(or 0)=0, extractIndex=31 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_DC_Power_SF channels updated: {modbus:data:SE7K:Registers:I_DC_Power_SF:number=0}. readValueType=int16, readIndex=Optional[101], readSubIndex(or 0)=0, extractIndex=32 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.594 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_Temp_Sink channels updated: {modbus:data:SE7K:Registers:I_Temp_Sink:number=0}. readValueType=int16, readIndex=Optional[103], readSubIndex(or 0)=0, extractIndex=34 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.595 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_Temp_SF channels updated: {modbus:data:SE7K:Registers:I_Temp_SF:number=-2}. readValueType=int16, readIndex=Optional[106], readSubIndex(or 0)=0, extractIndex=37 -> numeric value -2 and boolValue=true. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.595 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_Status channels updated: {modbus:data:SE7K:Registers:I_Status:number=2}. readValueType=uint16, readIndex=Optional[107], readSubIndex(or 0)=0, extractIndex=38 -> numeric value 2 and boolValue=true. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.595 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:SE7K:Registers:I_Status_Vendor channels updated: {}. readValueType=uint16, readIndex=Optional[109], readSubIndex(or 0)=0, extractIndex=40 -> numeric value 65535 and boolValue=true. Registers ModbusRegisterArrayImpl(00 67 00 32 00 00 00 00 00 00 00 00 ff fe 10 25 10 27 10 2f 09 59 09 4d 09 58 ff ff 00 00 00 00 13 86 ff fe 00 00 00 00 00 00 00 00 00 00 00 00 00 1f f5 25 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 80 00 00 00 80 00 80 00 ff fe 00 02 00 00 ff ff ff ff ff ff ff ff 00 00 00 00 ff ff ff ff ff ff ff ff) for request ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]
2020-08-30 22:06:51.595 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 65 ms, connection: 0, transaction=47, callback=18} [operation ID 860ea78f-6b1d-4b52-ba7c-7e7cd3282621]
2020-08-30 22:06:51.595 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (5000ms) poll task BasicPollTask@298f7c24[request=ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@1cf3e710[address=10.0.0.34,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@79ce8f44,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@79ce8f44] finished at 1598818011595. Was started at millis: 1598818011529 (=duration of 66 millis)
2020-08-30 22:06:56.867 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (5000ms) poll task BasicPollTask@298f7c24[request=ModbusPollerThingHandler.ModbusPollerReadRequest@686274eb[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@1cf3e710[address=10.0.0.34,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@79ce8f44,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@79ce8f44]. Current millis: 1598818016863

My thing (SolarEDGE SE7K inverter):

Bridge modbus:tcp:SE7K [ host="10.0.0.34", port=502, id=1, timeBetweenTransactionsMillis=150, 
timeBetweenReconnectMillis=1000, connectMaxTries=3, reconnectAfterMillis=60000, connectTimeoutMillis=1000 ] {  //Tried this with many different settings as recommended in various modbus topics.

Bridge poller Registers [ start=69, length=50, refresh=5000, type="holding" ] {
  // Setting polling to 1000 ms sometimes led to strange values in I_AC_POWER

    //Thing data C_DeviceAddress   [ readStart="68", readValueType="uint16" ]        // MODBUS Unit ID
    Thing data C_SunSpec_DID     [ readStart="69", readValueType="uint16" ]        // 101 = single phase, 102 = split phase, 103 = three phase 
    Thing data C_SunSpec_Length  [ readStart="70", readValueType="uint16" ]        // 50 = Length of model block
    Thing data I_AC_Current      [ readStart="71", readValueType="uint16" ]        // AC Total Current value
    Thing data I_AC_CurrentA     [ readStart="72", readValueType="uint16" ]        // AC Phase A Current value
    Thing data I_AC_CurrentB     [ readStart="73", readValueType="uint16" ]        // AC Phase B Current value
    Thing data I_AC_CurrentC     [ readStart="74", readValueType="uint16" ]        // AC Phase C Current value
    Thing data I_AC_Current_SF   [ readStart="75", readValueType="int16"  ]        // AC Current scale factor
    Thing data I_AC_VoltageAB    [ readStart="76", readValueType="uint16" ]        // AC Voltage Phase AB value
    Thing data I_AC_VoltageBC    [ readStart="77", readValueType="uint16" ]        // AC Voltage Phase BC value
    Thing data I_AC_VoltageCA    [ readStart="78", readValueType="uint16" ]        // AC Voltage Phase CA value
    Thing data I_AC_VoltageAN    [ readStart="79", readValueType="uint16" ]        // AC Voltage Phase A to N value
    Thing data I_AC_VoltageBN    [ readStart="80", readValueType="uint16" ]        // AC Voltage Phase B to N value
    Thing data I_AC_VoltageCN    [ readStart="81", readValueType="uint16" ]        // AC Voltage Phase C to N value
    Thing data I_AC_Voltage_SF   [ readStart="82", readValueType="int16"  ]        // AC Voltage scale factor
    Thing data I_AC_Power        [ readStart="83", readValueType="int16"  ]        // AC Power value
    Thing data I_AC_Power_SF     [ readStart="84", readValueType="int16"  ]        // AC Power scale factor
    Thing data I_AC_Frequency    [ readStart="85", readValueType="uint16" ]        // AC Frequency value
    Thing data I_AC_Frequency_SF [ readStart="86", readValueType="int16"  ]        // Scale factor
    Thing data I_AC_VA           [ readStart="87", readValueType="int16"  ]        // Apparent Power
    Thing data I_AC_VA_SF        [ readStart="88", readValueType="int16"  ]        // Scale factor
    Thing data I_AC_VAR          [ readStart="89", readValueType="int16"  ]        // Reactive Power
    Thing data I_AC_VAR_SF       [ readStart="90", readValueType="int16"  ]        // Scale factor
    Thing data I_AC_PF           [ readStart="91", readValueType="int16"  ]        // Power Factor
    Thing data I_AC_PF_SF        [ readStart="92", readValueType="int16"  ]        // Scale factor
    Thing data I_AC_Energy_WH    [ readStart="93", readValueType="int32"  ]        // AC Lifetime Energy Production
    Thing data I_AC_Energy_WH_SF [ readStart="95", readValueType="uint16" ]        // Scale factor
    Thing data I_DC_Current      [ readStart="96", readValueType="uint16" ]        // DC Current value
    Thing data I_DC_Current_SF   [ readStart="97", readValueType="int16"  ]        // Scale factor
    Thing data I_DC_Voltage      [ readStart="98", readValueType="uint16" ]        // DC Voltage value
    Thing data I_DC_Voltage_SF   [ readStart="99", readValueType="int16"  ]        // Scale factor
    Thing data I_DC_Power        [ readStart="100", readValueType="int16" ]        // DC Power value
    Thing data I_DC_Power_SF     [ readStart="101", readValueType="int16" ]        // Scale factor
    Thing data I_Temp_Sink       [ readStart="103", readValueType="int16" ]        // Heat sink temperature
    Thing data I_Temp_SF         [ readStart="106", readValueType="int16" ]        // Scale factor
    Thing data I_Status          [ readStart="107", readValueType="uint16"]        // Operating state
    Thing data I_Status_Vendor   [ readStart="109", readValueType="uint16"]        //     Vendor-defined operating state and error codes

    }

}

Modbus binding:

300 │ Active │  80 │ 2.5.8                   │ org.openhab.binding.modbus
301 │ Active │  80 │ 2.5.8                   │ org.openhab.binding.modbus.sunspec
302 │ Active │  80 │ 2.5.8                   │ org.openhab.io.transport.modbus

Running on Ubuntu 20.04.1 (and before yesterday 18.04.5) in a LXC container on an Ubuntu 18.04.5 host.

I’ll delete the sunspec bundle for now, lets see if that makes any difference.

Edit: After changing something in my thing this error comes up, after which the binding starts to work. Still a NPE is not good I guess:

86

@stfn82

Edit: After changing something in my thing this error comes up, after which the binding starts to work. Still a NPE is not good I guess:

What do you mean? I do not see any NullPointerException (NPE).

@BHall I do not understand what you are trying to say with the log levels … Sounds you can reproduce the polling issue by changing log level? That’s great if that is the case – we can use that to troubleshoot it faster. I did not manage to do this myself with simple setup so there must be more to it.

Both @BHall & @stfn82: when the polling stops, please follow the advice set in this post

i.e.

Please execute the following two commands in karaf console when the polling stops

threads --locks --monitors

and

threads

Looks like logs are not helping much at the moment… All I can say is that it looks that there is some sort of deadlock happening somewhere in the binding.

87

Sorry, I read to fast. Line 5 in the pastebin:

Error was: java.lang.InterruptedException null

Next time the polling stops I’ll run those 2 commands.

88

I’m sorry I did not explain clearly, I will try again:

I did a clean install with the openhab stable 2.5.8 that you recommended and installed the modbus binding from the PaperUI.

Lately I have been using these prior instructions for testing:

With logging set as above and poll rate of 30 sec everything worked well for hours.

I later tried setting poll rate of 1000 ms and everything continued to work well for hours.

Most recently I tried poll rate of 250 ms and once again everything continued to work well for hours.

I then issued the following commands to try without all the DEBUG entries.
openhab> log:set INFO org.openhab.io.transport.modbus
openhab> log:set INFO org.openhab.binding.modbus

After this change I operated a discrete input to cause the value of the register being read to change, and the change was reflected in the events log. I did this multiple times.

After a short period of time the event logging stopped completely, no
HVAC_Temp_Last_Success entries or entries when operating a discrete input to cause the value of the register being read to change.

I have found this to be repeatable,

I will try to reproduce the problem and execute the two commands you requested earlier.

Thanks!

89

@ssalonen,

Reproducing the issue did not take long.
Following is the result of the first command per your request:
The results of the second command will follow in another post.

openhab> threads --locks --monitors
"CM Configuration Updater" Id=28 in WAITING on lock=java.util.LinkedList@1c9f2b75
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:79)
    at java.lang.Thread.run(Thread.java:748)

"CM Event Dispatcher" Id=29 in WAITING on lock=java.util.LinkedList@5382a099
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:79)
    at java.lang.Thread.run(Thread.java:748)

"fileinstall-C:\openhab2/addons" Id=43 in TIMED_WAITING on lock=org.apache.felix.fileinstall.internal.DirectoryWatcher@2e8c2bcf
    at java.lang.Object.wait(Native Method)
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:320)

"encryption-1-thread-1" Id=54 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@29e665e1
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
    at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
    at sun.nio.fs.AbstractWatchService.poll(AbstractWatchService.java:108)
    at org.apache.karaf.jaas.modules.properties.AutoEncryptionSupport.run(AutoEncryptionSupport.java:94)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@690d00f8

"openHAB-job-scheduler_QuartzSchedulerThread" Id=120 in TIMED_WAITING on lock=java.lang.Object@27a8ac47
    at java.lang.Object.wait(Native Method)
    at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:410)

"main" Id=1 in WAITING on lock=java.util.concurrent.atomic.AtomicReference@787675d4
    at java.lang.Object.wait(Native Method)
    at org.eclipse.osgi.container.SystemModule.waitForStop(SystemModule.java:168)
    at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle.waitForStop(EquinoxBundle.java:250)
    at org.eclipse.osgi.launch.Equinox.waitForStop(Equinox.java:181)
    at org.apache.karaf.main.Main.awaitShutdown(Main.java:661)
    at org.apache.karaf.main.Main.main(Main.java:188)

"Framework Event Dispatcher: org.eclipse.osgi.internal.framework.EquinoxEventPublisher@16150369" Id=14 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@5b4191be
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Bundle File Closer" Id=15 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@3ee0c194
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Start Level: Equinox Container: 6ca2d9d4-f86a-4fe1-9e2e-7fa6c540ee15" Id=16 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@23e72627
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Karaf Lock Monitor Thread" Id=17 in TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at org.apache.karaf.main.Main.doMonitor(Main.java:410)
    at org.apache.karaf.main.Main.access$100(Main.java:74)
    at org.apache.karaf.main.Main$3.run(Main.java:377)

"Karaf Shutdown Socket Thread" Id=18 in RUNNABLE (running in native)
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
      - locked java.net.SocksSocketImpl@78203061
    at java.net.ServerSocket.implAccept(ServerSocket.java:562)
    at java.net.ServerSocket.accept(ServerSocket.java:530)
    at org.apache.karaf.main.ShutdownSocketThread.run(ShutdownSocketThread.java:66)

    Locked monitors: count = 1
      - java.net.SocksSocketImpl@78203061 locked at
          3 java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)

"fileinstall-C:\openhab2\userdata/etc" Id=32 in TIMED_WAITING on lock=org.apache.felix.fileinstall.internal.DirectoryWatcher@7b8aeb47
    at java.lang.Object.wait(Native Method)
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:320)

"WindowsStreamPump" Id=41 in RUNNABLE (running in native)
    at org.fusesource.jansi.internal.Kernel32.WaitForSingleObject(Native Method)
    at org.fusesource.jansi.internal.WindowsSupport.readConsoleInput(WindowsSupport.java:97)
    at org.jline.terminal.impl.jansi.win.JansiWinSysTerminal.processConsoleInput(JansiWinSysTerminal.java:112)
    at org.jline.terminal.impl.AbstractWindowsTerminal.pump(AbstractWindowsTerminal.java:458)
    at org.jline.terminal.impl.AbstractWindowsTerminal$$Lambda$36/1828489944.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

"Karaf local console user openhab" Id=45 in WAITING on lock=org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl@559b92dc
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.start(CommandSessionImpl.java:802)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:300)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:169)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:149)
    at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:179)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.doExecute(ConsoleSessionImpl.java:467)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:407)
    at java.lang.Thread.run(Thread.java:748)

"SCR Component Actor" Id=51 in WAITING on lock=java.util.LinkedList@7037f5a3
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:83)
    at java.lang.Thread.run(Thread.java:748)

"encryption-3-thread-1" Id=58 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@245661e5
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
    at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
    at sun.nio.fs.AbstractWatchService.poll(AbstractWatchService.java:108)
    at org.apache.karaf.jaas.modules.properties.AutoEncryptionSupport.run(AutoEncryptionSupport.java:94)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@8e6490b

"EMF Reference Cleaner" Id=70 in WAITING on lock=java.lang.ref.ReferenceQueue$Lock@61a715f3
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at org.eclipse.emf.common.util.CommonUtil$1ReferenceClearingQueuePollingThread.run(CommonUtil.java:70)

"OH-OSGiEventManager" Id=71 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2814b523
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
    at org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0(ThreadedEventHandler.java:60)
    at org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$340/586337187.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-77" Id=77 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@2e9090f0
      - locked java.util.Collections$UnmodifiableSet@7cc6a79d
      - locked sun.nio.ch.WindowsSelectorImpl@d14b11
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@2e9090f0 locked at 
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@7cc6a79d locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@d14b11 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"qtp2109812754-78" Id=78 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@51f07e89
      - locked java.util.Collections$UnmodifiableSet@23abe81c
      - locked sun.nio.ch.WindowsSelectorImpl@31e6638e
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@51f07e89 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@23abe81c locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@31e6638e locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"qtp2109812754-80-acceptor-0@5bfd5f8c-0.0.0.0:8443@f037769{SSL,[ssl, http/1.1]}{0.0.0.0:8443}" Id=80 in RUNNABLE (running in native)
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:419)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)
      - locked java.lang.Object@659ef827
    at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:385)
    at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:664)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 1
      - java.lang.Object@659ef827 locked at
          2 sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)

"qtp2109812754-81" Id=81 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@3d539cf6
      - locked java.util.Collections$UnmodifiableSet@4ecb64b2
      - locked sun.nio.ch.WindowsSelectorImpl@7c81d50e
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@3d539cf6 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@4ecb64b2 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@7c81d50e locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"qtp2109812754-82" Id=82 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@35c8d46a
      - locked java.util.Collections$UnmodifiableSet@5d3de8a5
      - locked sun.nio.ch.WindowsSelectorImpl@2be64c1d
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@35c8d46a locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@5d3de8a5 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@2be64c1d locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"qtp2109812754-83-acceptor-0@30785c11-default@41b769d2{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}" Id=83 in RUNNABLE (running in native)
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:419)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)
      - locked java.lang.Object@31d4eef1
    at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:385)
    at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:664)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 1
      - java.lang.Object@31d4eef1 locked at
          2 sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)

"Dir Watcher" Id=90 in WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@1d7d7a0d
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)
    at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492)
    at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680)
    at sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118)
    at org.eclipse.smarthome.core.service.WatchQueueReader.run(WatchQueueReader.java:210)
    at java.lang.Thread.run(Thread.java:748)

"com.google.inject.internal.util.$Finalizer" Id=102 in WAITING on lock=java.lang.ref.ReferenceQueue$Lock@10d78a51
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at com.google.inject.internal.util.$Finalizer.run(Finalizer.java:114)

"openHAB-job-scheduler_Worker-1" Id=110 in TIMED_WAITING on lock=java.lang.Object@6bdeddb1
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-2" Id=111 in TIMED_WAITING on lock=java.lang.Object@137fada3
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-3" Id=112 in TIMED_WAITING on lock=java.lang.Object@60a7ff7a
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-4" Id=113 in TIMED_WAITING on lock=java.lang.Object@4e6861a4
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-5" Id=114 in TIMED_WAITING on lock=java.lang.Object@40071bd6
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-6" Id=115 in TIMED_WAITING on lock=java.lang.Object@62023538
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-7" Id=116 in TIMED_WAITING on lock=java.lang.Object@3c125e65
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-8" Id=117 in TIMED_WAITING on lock=java.lang.Object@5eba1b61
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-9" Id=118 in TIMED_WAITING on lock=java.lang.Object@70ca5dab
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-10" Id=119 in TIMED_WAITING on lock=java.lang.Object@301dda6d
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"lsp-1" Id=126 in RUNNABLE (running in native)
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
      - locked java.net.SocksSocketImpl@a91bb79
    at java.net.ServerSocket.implAccept(ServerSocket.java:562)
    at java.net.ServerSocket.accept(ServerSocket.java:530)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer.listen(ModelServer.java:98)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer.lambda$0(ModelServer.java:77)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer$$Lambda$448/1295336421.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@12d462ac

    Locked monitors: count = 1
      - java.net.SocksSocketImpl@a91bb79 locked at
          3 java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)

"ServletModel-12-133" Id=133 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@3b2960ca
      - locked java.util.Collections$UnmodifiableSet@10dc8051
      - locked sun.nio.ch.WindowsSelectorImpl@3efd6d6d
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@3b2960ca locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@10dc8051 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@3efd6d6d locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"ServletModel-12-134" Id=134 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-135" Id=135 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-136" Id=136 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-137" Id=137 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-138" Id=138 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-139" Id=139 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-140" Id=140 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@4136dbaf
      - locked java.util.Collections$UnmodifiableSet@2f5091d7
      - locked sun.nio.ch.WindowsSelectorImpl@40cdc857
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

    Locked monitors: count = 3
      - sun.nio.ch.Util$3@4136dbaf locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - java.util.Collections$UnmodifiableSet@2f5091d7 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - sun.nio.ch.WindowsSelectorImpl@40cdc857 locked at
          4 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"OH-modbusManagerPollerThreadPool-2" Id=144 in WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4f041ed4
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)
    at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:587)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:366)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:281)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.borrowConnection(ModbusManagerImpl.java:380)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.lambda$3(ModbusManagerImpl.java:463)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$$Lambda$532/403166972.get(Unknown Source)
    at org.openhab.io.transport.modbus.internal.SimpleStopWatch.timeSupplier(SimpleStopWatch.java:118)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.getConnection(ModbusManagerImpl.java:463)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.executeOperation(ModbusManagerImpl.java:556)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.access$2(ModbusManagerImpl.java:525)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$ModbusCommunicationInterfaceImpl.lambda$1(ModbusManagerImpl.java:782)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$ModbusCommunicationInterfaceImpl$$Lambda$530/578027160.run(Unknown Source)        
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@782829b3

"SocketListener(JmDNS-/192.168.1.43)" Id=165 in RUNNABLE (running in native)
    at java.net.TwoStacksPlainDatagramSocketImpl.receive0(Native Method)
      - locked java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc
    at java.net.TwoStacksPlainDatagramSocketImpl.receive(TwoStacksPlainDatagramSocketImpl.java:114)
      - locked java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc
    at java.net.DatagramSocket.receive(DatagramSocket.java:812)
      - locked java.net.DatagramPacket@3137424d
      - locked java.net.MulticastSocket@2dd87a04
    at javax.jmdns.impl.SocketListener.run(SocketListener.java:41)

    Locked monitors: count = 4
      - java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc locked at
          0 java.net.TwoStacksPlainDatagramSocketImpl.receive0(Native Method)
      - java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc locked at
          1 java.net.TwoStacksPlainDatagramSocketImpl.receive(TwoStacksPlainDatagramSocketImpl.java:114)
      - java.net.DatagramPacket@3137424d locked at
          2 java.net.DatagramSocket.receive(DatagramSocket.java:812)
      - java.net.MulticastSocket@2dd87a04 locked at
          2 java.net.DatagramSocket.receive(DatagramSocket.java:812)

"job controller 1" Id=472 in WAITING on lock=java.util.concurrent.FutureTask@312cb1e5
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
    at java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:244)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.run(CommandSessionImpl.java:827)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@5f658561

"pipe-threads --locks --monitors" Id=473 in RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
    at org.apache.karaf.shell.commands.impl.ThreadsAction.execute(ThreadsAction.java:78)
    at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:84)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86)
    at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:599)
    at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:526)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:415)
    at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:416)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@6eec27cc

openhab>
90

@ssalonen,
Following is the result of the second command per your request:
I had a little issue so if the results from either of the commands does not look right let me know and I will repeat the test.

openhab> threads
"CM Configuration Updater" Id=28 in WAITING on lock=java.util.LinkedList@1c9f2b75
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:79)
    at java.lang.Thread.run(Thread.java:748)

"CM Event Dispatcher" Id=29 in WAITING on lock=java.util.LinkedList@5382a099
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:79)
    at java.lang.Thread.run(Thread.java:748)

"fileinstall-C:\openhab2/addons" Id=43 in TIMED_WAITING on lock=org.apache.felix.fileinstall.internal.DirectoryWatcher@2e8c2bcf
    at java.lang.Object.wait(Native Method)
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:320)

"encryption-1-thread-1" Id=54 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@29e665e1
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
    at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
    at sun.nio.fs.AbstractWatchService.poll(AbstractWatchService.java:108)
    at org.apache.karaf.jaas.modules.properties.AutoEncryptionSupport.run(AutoEncryptionSupport.java:94)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"openHAB-job-scheduler_QuartzSchedulerThread" Id=120 in TIMED_WAITING on lock=java.lang.Object@27a8ac47
    at java.lang.Object.wait(Native Method)
    at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:410)

"main" Id=1 in WAITING on lock=java.util.concurrent.atomic.AtomicReference@787675d4
    at java.lang.Object.wait(Native Method)
    at org.eclipse.osgi.container.SystemModule.waitForStop(SystemModule.java:168)
    at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle.waitForStop(EquinoxBundle.java:250)
    at org.eclipse.osgi.launch.Equinox.waitForStop(Equinox.java:181)
    at org.apache.karaf.main.Main.awaitShutdown(Main.java:661)
    at org.apache.karaf.main.Main.main(Main.java:188)

"Framework Event Dispatcher: org.eclipse.osgi.internal.framework.EquinoxEventPublisher@16150369" Id=14 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@5b4191be
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Bundle File Closer" Id=15 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@3ee0c194
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Start Level: Equinox Container: 6ca2d9d4-f86a-4fe1-9e2e-7fa6c540ee15" Id=16 in WAITING on lock=org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@23e72627
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:336)

"Karaf Lock Monitor Thread" Id=17 in TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at org.apache.karaf.main.Main.doMonitor(Main.java:410)
    at org.apache.karaf.main.Main.access$100(Main.java:74)
    at org.apache.karaf.main.Main$3.run(Main.java:377)

"Karaf Shutdown Socket Thread" Id=18 in RUNNABLE (running in native)
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
      - locked java.net.SocksSocketImpl@78203061
    at java.net.ServerSocket.implAccept(ServerSocket.java:562)
    at java.net.ServerSocket.accept(ServerSocket.java:530)
    at org.apache.karaf.main.ShutdownSocketThread.run(ShutdownSocketThread.java:66)

"fileinstall-C:\openhab2\userdata/etc" Id=32 in TIMED_WAITING on lock=org.apache.felix.fileinstall.internal.DirectoryWatcher@7b8aeb47
    at java.lang.Object.wait(Native Method)
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:320)

"WindowsStreamPump" Id=41 in RUNNABLE (running in native)
    at org.fusesource.jansi.internal.Kernel32.WaitForSingleObject(Native Method)
    at org.fusesource.jansi.internal.WindowsSupport.readConsoleInput(WindowsSupport.java:97)
    at org.jline.terminal.impl.jansi.win.JansiWinSysTerminal.processConsoleInput(JansiWinSysTerminal.java:112)
    at org.jline.terminal.impl.AbstractWindowsTerminal.pump(AbstractWindowsTerminal.java:458)
    at org.jline.terminal.impl.AbstractWindowsTerminal$$Lambda$36/1828489944.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

"Karaf local console user openhab" Id=45 in WAITING on lock=org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl@334c72b
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.start(CommandSessionImpl.java:802)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:300)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:169)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:149)
    at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:179)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.doExecute(ConsoleSessionImpl.java:467)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:407)
    at java.lang.Thread.run(Thread.java:748)

"SCR Component Actor" Id=51 in WAITING on lock=java.util.LinkedList@7037f5a3
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:83)
    at java.lang.Thread.run(Thread.java:748)

"encryption-3-thread-1" Id=58 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@245661e5
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
    at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
    at sun.nio.fs.AbstractWatchService.poll(AbstractWatchService.java:108)
    at org.apache.karaf.jaas.modules.properties.AutoEncryptionSupport.run(AutoEncryptionSupport.java:94)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"EMF Reference Cleaner" Id=70 in WAITING on lock=java.lang.ref.ReferenceQueue$Lock@61a715f3
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at org.eclipse.emf.common.util.CommonUtil$1ReferenceClearingQueuePollingThread.run(CommonUtil.java:70)

"OH-OSGiEventManager" Id=71 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2814b523
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
    at org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0(ThreadedEventHandler.java:60)
    at org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$340/586337187.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-77" Id=77 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@2e9090f0
      - locked java.util.Collections$UnmodifiableSet@7cc6a79d
      - locked sun.nio.ch.WindowsSelectorImpl@d14b11
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-78" Id=78 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@51f07e89
      - locked java.util.Collections$UnmodifiableSet@23abe81c
      - locked sun.nio.ch.WindowsSelectorImpl@31e6638e
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-80-acceptor-0@5bfd5f8c-0.0.0.0:8443@f037769{SSL,[ssl, http/1.1]}{0.0.0.0:8443}" Id=80 in RUNNABLE (running in native)
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:419)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)
      - locked java.lang.Object@659ef827
    at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:385)
    at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:664)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-81" Id=81 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@3d539cf6
      - locked java.util.Collections$UnmodifiableSet@4ecb64b2
      - locked sun.nio.ch.WindowsSelectorImpl@7c81d50e
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-82" Id=82 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@35c8d46a
      - locked java.util.Collections$UnmodifiableSet@5d3de8a5
      - locked sun.nio.ch.WindowsSelectorImpl@2be64c1d
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"qtp2109812754-83-acceptor-0@30785c11-default@41b769d2{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}" Id=83 in RUNNABLE (running in native)
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:419)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:247)
      - locked java.lang.Object@31d4eef1
    at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:385)
    at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:664)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"Dir Watcher" Id=90 in WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@1d7d7a0d
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)
    at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492)
    at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680)
    at sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118)
    at org.eclipse.smarthome.core.service.WatchQueueReader.run(WatchQueueReader.java:210)
    at java.lang.Thread.run(Thread.java:748)

"com.google.inject.internal.util.$Finalizer" Id=102 in WAITING on lock=java.lang.ref.ReferenceQueue$Lock@10d78a51
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at com.google.inject.internal.util.$Finalizer.run(Finalizer.java:114)

"openHAB-job-scheduler_Worker-1" Id=110 in TIMED_WAITING on lock=java.lang.Object@6bdeddb1
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-2" Id=111 in TIMED_WAITING on lock=java.lang.Object@137fada3
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-3" Id=112 in TIMED_WAITING on lock=java.lang.Object@60a7ff7a
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-4" Id=113 in TIMED_WAITING on lock=java.lang.Object@4e6861a4
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-5" Id=114 in TIMED_WAITING on lock=java.lang.Object@40071bd6
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-6" Id=115 in TIMED_WAITING on lock=java.lang.Object@62023538
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-7" Id=116 in TIMED_WAITING on lock=java.lang.Object@3c125e65
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-8" Id=117 in TIMED_WAITING on lock=java.lang.Object@5eba1b61
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-9" Id=118 in TIMED_WAITING on lock=java.lang.Object@70ca5dab
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"openHAB-job-scheduler_Worker-10" Id=119 in TIMED_WAITING on lock=java.lang.Object@301dda6d
    at java.lang.Object.wait(Native Method)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)

"lsp-1" Id=126 in RUNNABLE (running in native)
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
      - locked java.net.SocksSocketImpl@a91bb79
    at java.net.ServerSocket.implAccept(ServerSocket.java:562)
    at java.net.ServerSocket.accept(ServerSocket.java:530)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer.listen(ModelServer.java:98)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer.lambda$0(ModelServer.java:77)
    at org.eclipse.smarthome.model.lsp.internal.ModelServer$$Lambda$448/1295336421.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-133" Id=133 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@3b2960ca
      - locked java.util.Collections$UnmodifiableSet@10dc8051
      - locked sun.nio.ch.WindowsSelectorImpl@3efd6d6d
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-134" Id=134 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-135" Id=135 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-136" Id=136 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-137" Id=137 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-138" Id=138 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-139" Id=139 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4cb53150
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2083)
    at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:851)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:890)
    at java.lang.Thread.run(Thread.java:748)

"ServletModel-12-140" Id=140 in RUNNABLE (running in native)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:314)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:293)
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:174)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
      - locked sun.nio.ch.Util$3@4136dbaf
      - locked java.util.Collections$UnmodifiableSet@2f5091d7
      - locked sun.nio.ch.WindowsSelectorImpl@40cdc857
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:466)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:403)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.io.ManagedSelector$$Lambda$373/1331947632.run(Unknown Source)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
    at java.lang.Thread.run(Thread.java:748)

"OH-modbusManagerPollerThreadPool-2" Id=144 in WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4f041ed4
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)
    at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:587)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:366)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:281)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.borrowConnection(ModbusManagerImpl.java:380)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.lambda$3(ModbusManagerImpl.java:463)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$$Lambda$532/403166972.get(Unknown Source)
    at org.openhab.io.transport.modbus.internal.SimpleStopWatch.timeSupplier(SimpleStopWatch.java:118)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.getConnection(ModbusManagerImpl.java:463)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.executeOperation(ModbusManagerImpl.java:556)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.access$2(ModbusManagerImpl.java:525)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$ModbusCommunicationInterfaceImpl.lambda$1(ModbusManagerImpl.java:782)
    at org.openhab.io.transport.modbus.internal.ModbusManagerImpl$ModbusCommunicationInterfaceImpl$$Lambda$530/578027160.run(Unknown Source)        
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"SocketListener(JmDNS-/192.168.1.43)" Id=165 in RUNNABLE (running in native)
    at java.net.TwoStacksPlainDatagramSocketImpl.receive0(Native Method)
      - locked java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc
    at java.net.TwoStacksPlainDatagramSocketImpl.receive(TwoStacksPlainDatagramSocketImpl.java:114)
      - locked java.net.TwoStacksPlainDatagramSocketImpl@3086a3fc
    at java.net.DatagramSocket.receive(DatagramSocket.java:812)
      - locked java.net.DatagramPacket@3137424d
      - locked java.net.MulticastSocket@2dd87a04
    at javax.jmdns.impl.SocketListener.run(SocketListener.java:41)

"job controller 1" Id=544 in WAITING on lock=java.util.concurrent.FutureTask@7e58ad81
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
    at java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:244)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.run(CommandSessionImpl.java:827)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pipe-threads" Id=545 in RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
    at org.apache.karaf.shell.commands.impl.ThreadsAction.execute(ThreadsAction.java:78)
    at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:84)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86)
    at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:599)
    at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:526)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:415)
    at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:416)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

openhab>
91

Thank you @BHall

Since I cannot reproduce the issue myself this is a bit shot in the dark but let’s see…

Please install the following versions of modbus binding and transport:

modbus-2.5.8-disabled-eviction.zip.pdf (309.5 KB)

For installation instructions, please follow the step outlined in this post:

Instead of using files from ci.openhab.org, please use the attached zip file (rename the .pdf to .zip for extraction).

After executing the installation steps, please output bundle:list -s|grep modbus and try to get the reproduce the issue with the new version.