Random Response Times or No Execution

[mccormack (Adam McCormack)]

Hi All,

Here’s the basics:

• Raspberry Pi 4 and Raspberry Pi 3B+
• Aeotec Z-stick and Go Control HUSBZB-1
• OpenHAB 2.5

So for a long time I have experienced random response times and/or no response. Most of the time it’s Zwave related. It’s random whether it’s instant, up to a minute delay or not at all. And it doesn’t matter if it’s a simple rule or a scene or something more complex.

If it helps occasionally openhab.log stops updating even though events log keep going.

I have tried:

• Numerous Rasberry Pi’s - running openhabian, Wheezy and Buster

• 3 different Zwave controllers (2 aeotec and 1 Go control).

• Multiple SD cards and SSD’s

• External USB hub with dedicated power.

• Different switches (GE and Inovelli)

Here’s a simple rule and the logs that goes with it. In this instance there was no response at all. This switch in question is about 10 feet away from the controller and through one wall. It’s also one that has been replaced for testing.

In the events log it is being seen as changing on and off.

Any ideas or even where to go from here is greatly appreciated.

rule "garage"
when Item Garage_Switch changed
then
	if (Garage_Switch.state==ON) {
		logInfo("Garage", "Light is on.")
		Garage_Sign.sendCommand(ON)
		Garage_Outlet.sendCommand(ON)
	}
	else if (Garage_Switch.state==OFF) {
		logInfo("Garage", "Light is off."
		Garage_Sign.sendCommand(OFF)
		Garage_Outlet.sendCommand(OFF)
	}
end

OpenHAB log

2020-02-03 17:03:30.623 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-02-03 17:03:30.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-03 17:03:30.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-03 17:03:30.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-03 17:03:41.118 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-02-03 17:03:41.282 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-02-03 17:04:02.208 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 25 
2020-02-03 17:04:02.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:02.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:02.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-03 17:04:02.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2020-02-03 17:04:02.223 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2020-02-03 17:04:02.225 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:02.227 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node information received. Transaction null
2020-02-03 17:04:02.228 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2020-02-03 17:04:02.230 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update - no transaction.
2020-02-03 17:04:02.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-03 17:04:02.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-03 17:04:02.278 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 25 03 FF 2A 
2020-02-03 17:04:02.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 25 03 FF 
2020-02-03 17:04:02.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 25 03 FF 
2020-02-03 17:04:02.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-03 17:04:02.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2020-02-03 17:04:02.288 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2020-02-03 17:04:02.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2020-02-03 17:04:02.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2020-02-03 17:04:02.291 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2020-02-03 17:04:02.293 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 255
2020-02-03 17:04:02.294 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-02-03 17:04:02.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
2020-02-03 17:04:02.297 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:b7428e83:node2:switch_binary to ON [OnOffType]
2020-02-03 17:04:02.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2020-02-03 17:04:02.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@16d335.
2020-02-03 17:04:02.304 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for Garage_Switch
2020-02-03 17:04:02.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-03 17:04:02.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-03 17:04:02.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-03 17:04:02.307 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'Garage_Switch' with state 'ON' in mapdb database
2020-02-03 17:04:02.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-03 17:04:02.309 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for gGarage
2020-02-03 17:04:02.312 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'gGarage' with state 'ON' in mapdb database
2020-02-03 17:04:15.670 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 25 
2020-02-03 17:04:15.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:15.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:15.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-03 17:04:15.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2020-02-03 17:04:15.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2020-02-03 17:04:15.692 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=2, callback=132, payload=84 02 11 04 10 01 5E 56 86 72 5A 85 59 73 25 27 70 2C 2B 7A 
2020-02-03 17:04:15.693 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node information received. Transaction null
2020-02-03 17:04:15.695 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2020-02-03 17:04:15.696 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update - no transaction.
2020-02-03 17:04:15.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-03 17:04:15.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-03 17:04:15.739 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 25 03 00 D5 
2020-02-03 17:04:15.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 25 03 00 
2020-02-03 17:04:15.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 25 03 00 
2020-02-03 17:04:15.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-03 17:04:15.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2020-02-03 17:04:15.754 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2020-02-03 17:04:15.755 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2020-02-03 17:04:15.756 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2020-02-03 17:04:15.757 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2020-02-03 17:04:15.758 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 0
2020-02-03 17:04:15.760 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-02-03 17:04:15.761 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
2020-02-03 17:04:15.763 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:b7428e83:node2:switch_binary to OFF [OnOffType]
2020-02-03 17:04:15.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2020-02-03 17:04:15.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@14e6969.
2020-02-03 17:04:15.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-03 17:04:15.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-03 17:04:15.770 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for Garage_Switch
2020-02-03 17:04:15.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-03 17:04:15.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-03 17:04:15.773 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'Garage_Switch' with state 'OFF' in mapdb database
2020-02-03 17:04:15.776 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for gGarage
2020-02-03 17:04:15.782 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'gGarage' with state 'OFF' in mapdb database

Events Log

2020-02-03 17:03:30.056 [ome.event.ItemCommandEvent] - Item 'Entryway' received command REFRESH
2020-02-03 17:04:02.310 [vent.ItemStateChangedEvent] - Garage_Switch changed from OFF to ON
2020-02-03 17:04:02.312 [GroupItemStateChangedEvent] - gGarage changed from OFF to ON through Garage_Switch
2020-02-03 17:04:15.775 [vent.ItemStateChangedEvent] - Garage_Switch changed from ON to OFF
2020-02-03 17:04:15.778 [GroupItemStateChangedEvent] - gGarage changed from ON to OFF through Garage_Switch
2020-02-03 17:04:30.031 [ome.event.ItemCommandEvent] - Item 'Patrick_Lights' received command REFRESH

[H102 (CM6.5 H102)]

It’s would help if you provide all your item config’s as the logs mention groups and other items that we have no idea about.

If you go to the doctor and simply say “I don’t fell good” what response would you expect?

[rossko57]

@mccormack

Item ‘Entryway’ received command REFRESH

It is unusual to see this. Is this aimed at a zwave device? It shouldn’t be necessary, just adds network traffic.

@mccormack

[DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-02-03 17:03:41.282 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling ‘openhab-ui-dashboard’: Feature named ‘openhab-ui-dashboard/0’ is not installed

Is that happening periodically? That looks rather like the effect people see after a 2.5 upgrade associated with addons.config problems.

[Bruce_Osborne]

@rossko57

Is that happening periodically? That looks rather like the effect people see after a 2.5 upgrade associated with addons.config problems.

If that is the case, the binding is reloading every minute and response times would depend on where in that cycle the request falls.
restdocs moving was specifically mentioned both in the Release Notes and in the Warnings displayed in the CLI when upgrading. Some v1 bindings were moved to legacy too. in short, RTFM.

[H102 (CM6.5 H102)]

All the notes and info needed for 2.5 upgrade:

openhab/openhab-distro

[Bruce_Osborne]

This thread may be useful too.

2.5 issues after upgrade

This post is meant to summarize the most often encountered problems to appear after you upgraded your system to 2.5 (or 2.5.x, actually). I’ll update/extend it over time. Let me know if you feel there’s substantial stuff missing (issues) or insufficient (explanations how to fix). ** Anyone: ** ** Please check these out first before posting about your problem. ** Assumptions This post assumes you ran 2.4 before your upgrade. If you upgraded from some earlier version or some non-release versio…

[mccormack (Adam McCormack)]

Refresh - I put those there a long time ago because even if I changed the polling time it still didn’t reflect correctly. It’s been a while so I can try again without them. I understand the increased traffic.

Yes it happens frequently. I checked and dashboard UI shows in Paper UI but not in addons.config. addons.cfg is completely commented out. I did notice the TPLink binding was acting in the manner of the 2.5 update issues but couldn’t find anything else that pointed to that.

I tried uninstalling openhab-ui-dashboard through Karaf and ended up screwing everything up and had to reinstall. Still getting back to normal. Will have to wait and see how things go.

Thanks for pointing me in the right direction.