OH3.1.0 Z-Wave Scene Updates No Longer Triggering Rules

Last night I upgraded to 3.1.0 from one of the milestones and now several of my rules related to scene controllers are no longer working.

I can see in the logs and web console that the Z-Wave event is registering, but I cannot ever see the rule get triggered. I have tried bumping up the logging on both to see if there is some kind of error, but I am not seeing anything.

Here’s the logging settings I used and the output:

openhab> log:set DEBUG openhab.event.RuleStatusInfoEvent 
openhab> log:set DEBUG openhab.event.ItemStateEvent
openhab> log:set DEBUG org.openhab.binding.zwave
openhab> log:set DEBUG org.openhab.core.model.rule
openhab> log:tail
16:35:04.977 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 12 05 5B 03 CC 00 02 71 
16:35:04.982 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=18, callback=0, payload=00 12 05 5B 03 CC 00 02 
16:35:04.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=18, callback=0, payload=00 12 05 5B 03 CC 00 02 
16:35:04.987 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
16:35:04.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Application Command Request (ALIVE:DONE)
16:35:04.992 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
16:35:04.994 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: Incoming command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0
16:35:04.996 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
16:35:04.999 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 18: Received COMMAND_CLASS_CENTRAL_SCENE V2 CENTRAL_SCENE_NOTIFICATION
16:35:05.001 [DEBUG] [ndclass.ZWaveCentralSceneCommandClass] - NODE 18: Received scene 2 at key 0 [Single Press]
16:35:05.004 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
16:35:05.006 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_CENTRAL_SCENE, value=2.0
16:35:05.008 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Updating channel state zwave:device:3b823768:node18:scene_number to 2.0 [DecimalType]
16:35:05.011 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Commands processed 1.
16:35:05.013 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@48f031ff.
16:35:05.016 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:05.018 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:05.020 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
16:35:05.022 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
16:35:05.430 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 12 03 80 03 64 04 
16:35:05.435 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=18, callback=0, payload=00 12 03 80 03 64 
16:35:05.439 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=18, callback=0, payload=00 12 03 80 03 64 
16:35:05.443 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
16:35:05.445 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Application Command Request (ALIVE:DONE)
16:35:05.448 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
16:35:05.449 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
16:35:05.451 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
16:35:05.453 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 18: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
16:35:05.455 [DEBUG] [commandclass.ZWaveBatteryCommandClass] - NODE 18: Battery report value = 100
16:35:05.457 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
16:35:05.459 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=100
16:35:05.460 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 18: Updating channel state zwave:device:3b823768:node18:battery-level to 100 [DecimalType]
16:35:05.462 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Commands processed 1.
16:35:05.464 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 18: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@748c6ac5.
16:35:05.466 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:05.468 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:05.469 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
16:35:05.471 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
16:35:06.819 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 80 03 64 14 
16:35:06.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 
16:35:06.828 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 
16:35:06.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
16:35:06.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
16:35:06.838 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
16:35:06.841 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
16:35:06.843 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
16:35:06.845 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
16:35:06.847 [DEBUG] [commandclass.ZWaveBatteryCommandClass] - NODE 2: Battery report value = 100
16:35:06.849 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
16:35:06.851 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=100
16:35:06.853 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:1779cc6310c:node2:battery-level to 100 [DecimalType]
16:35:06.855 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
16:35:06.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@22dd7542.
16:35:06.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:06.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:35:06.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
16:35:06.865 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

OK, my “Hail Mary” play worked and after a couple of restarts it is working again.