Light turns on and off without cause or instruction

jeremyjjr · May 17, 2019, 8:59am

I’m running OH 2.5.0 M1 on Debian.

I have a z-wave light that is automatically turning on at around 2.15am every day and off a few minutes later. I have no rule set up to turn on this light and no one is awake flipping the switch manually! In the event.log I see this entry:

2019-05-17 02:20:25.246 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from OFF to ON
2019-05-17 02:20:25.247 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 0 to 75
2019-05-17 02:59:04.529 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from ON to OFF
2019-05-17 02:59:04.530 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 75 to 0

Can anyone help me understand what might be causing this device to turn on/off given there are no rules?

HomeAutomation · May 17, 2019, 9:25am

Please check if your wall switch is associated with the light switch.

grafik

sihui · May 17, 2019, 9:40am

… and some devices have an automated timer feature. Check your config parameters.

jeremyjjr · May 17, 2019, 10:31am

Thanks. The z-wave device is a Fibaro FGD212 Dimmer 2 and therefore controls both the switch and the light. There is a single association to another light, such that when the manual switch is used to turn on the ‘back wall’ light, the ‘front wall’ light turns on as well.

Interestingly, at night, when the back wall light automatically turns on, the front light does not - suggesting it’s again not the manual switch turning on the light - which I already knew! No inbuilt device timer

Andrew_Rowe · May 17, 2019, 10:52am

There’s a ghost in my house

sihui · May 17, 2019, 11:50am

It does have one, you might want to double check:

You might also check config parameter 24:

grafik

jeremyjjr · May 17, 2019, 1:54pm

Thanks. WRT timer - you are absolutely correct - thank you for highlighting that. I wasn’t aware of it. Sadly it’s only auto-off after a certain period of time, and it’s not set. I’m more concerned about why it’s turning on in the first place TBH.

I know I could increase debugging levels. But not sure which module (or how) as I think something else is telling the z-wave device to turn on.

sihui · May 17, 2019, 2:05pm

Go to the karaf console

and type

log:set DEBUG org.openhab.binding.zwave

rossko57 · May 17, 2019, 6:42pm

Well, the off remains a mystery as well, and you need clues, don’t discard them.
Is it always ghost-off 40 minutes after ghost-on? That suggests a deliberate (if hidden) control at work, not random events. If you switch on by hand, does it ever turn off unexpectedly?

jeremyjjr · May 17, 2019, 9:41pm

Good question! Here is another example, this time a little later in the early hours of the morning.

events.log.7:2019-05-16 03:33:12.423 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from OFF to ON
events.log.7:2019-05-16 03:33:12.424 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 0 to 75
events.log.7:2019-05-16 03:55:15.220 [ome.event.ItemCommandEvent] - Item 'light_back_wall_dm' received command 100
events.log.7:2019-05-16 03:55:15.221 [nt.ItemStatePredictedEvent] - light_back_wall_dm predicted to become 100
events.log.7:2019-05-16 03:55:15.222 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 75 to 100
events.log.7:2019-05-16 03:55:17.286 [ome.event.ItemCommandEvent] - Item 'light_back_wall_dm' received command 0
events.log.7:2019-05-16 03:55:17.290 [nt.ItemStatePredictedEvent] - light_back_wall_dm predicted to become 0
events.log.7:2019-05-16 03:55:17.292 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 100 to 0
events.log.7:2019-05-16 03:55:18.384 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from ON to OFF

This time just a 22 minute gap between the on and off events. I will try your suggestion of seeing if an auto-off occurs after manually left on over the weekend. Tonight I’m running the z-wave log in DEBUG to see what treasures that reveals!

rossko57 · May 17, 2019, 10:57pm

Woah, just a minute … where has that come from? A command means it is something that openHAB has done - originating from a UI, or a rule, or (rarely) a binding.
Time to show us Item, channel, Thing definitions.

jeremyjjr · May 17, 2019, 11:08pm

Ahh. My bad. Bad example. That was one occasion when I woke up and saw the light was on - proceeding then to turn the light off myself - hence the command! A better example would be:

2019-05-04 01:39:35.309 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from OFF to ON
2019-05-04 01:39:35.310 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 0 to 75
2019-05-04 02:23:45.381 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from ON to OFF
2019-05-04 02:23:45.382 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 75 to 0

But, to your point on item definitions …

Group:Switch:AND(ON,OFF)	light_outside_wall_sw	"Wall Lights"			<lightbulb>		(group_outside_lights)			
	Switch					light_front_wall_sw		"Front Wall Switch"						(light_outside_wall_sw)												{ channel = "zwave:device:512:node32:switch_dimmer1" }
	Switch					light_back_wall_sw		"Back Wall Switch"						(light_outside_wall_sw)												{ channel = "zwave:device:512:node9:switch_dimmer1" }

The ‘thing’ definition was created through HABadmin as it’s a z-wave device. If that’s needed, I’m not sure how to export it.

jeremyjjr · May 18, 2019, 8:38am

Same thing again last night. Entries from events.log are:

2019-05-18 02:45:12.735 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from OFF to ON
2019-05-18 02:45:12.735 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 0 to 75
2019-05-18 03:24:21.208 [vent.ItemStateChangedEvent] - light_back_wall_sw changed from ON to OFF
2019-05-18 03:24:21.209 [vent.ItemStateChangedEvent] - light_back_wall_dm changed from 75 to 0

And the corresponding entries from openhab.log:

2019-05-18 02:45:12.729 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 09 07 60 0D 01 01 26 03 4B FB
2019-05-18 02:45:12.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 07 60 0D 01 01 26 03 4B
2019-05-18 02:45:12.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 07 60 0D 01 01 26 03 4B
2019-05-18 02:45:12.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-05-18 02:45:12.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Application Command Request (ALIVE:DONE)
2019-05-18 02:45:12.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: resetResendCount initComplete=true isDead=false
2019-05-18 02:45:12.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-05-18 02:45:12.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
2019-05-18 02:45:12.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2019-05-18 02:45:12.732 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2019-05-18 02:45:12.732 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Switch Multi Level report, value = 75
2019-05-18 02:45:12.732 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-05-18 02:45:12.732 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 75
2019-05-18 02:45:12.732 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating channel state zwave:device:512:node9:switch_dimmer1 to 75 [PercentType]
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Commands processed 1.
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7bdad3de.
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-05-18 02:45:12.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-05-18 02:45:12.980 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 09 0A 60 0D 01 01 31 05 04 22 00 7A ED
2019-05-18 02:45:12.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 0A 60 0D 01 01 31 05 04 22 00 7A
2019-05-18 02:45:12.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 0A 60 0D 01 01 31 05 04 22 00 7A
2019-05-18 02:45:12.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-05-18 02:45:12.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Application Command Request (ALIVE:DONE)
2019-05-18 02:45:12.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: resetResendCount initComplete=true isDead=false
2019-05-18 02:45:12.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-05-18 02:45:12.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1
2019-05-18 02:45:12.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
2019-05-18 02:45:12.982 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT
2019-05-18 02:45:12.983 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Type = Power(4), Scale = 0
2019-05-18 02:45:12.983 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Value = 12.2
2019-05-18 02:45:12.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-05-18 02:45:12.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 12.2
2019-05-18 02:45:12.983 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 9: Sensor conversion not performed for POWER.
2019-05-18 02:45:12.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating channel state zwave:device:512:node9:sensor_power1 to 12.2 [DecimalType]
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Commands processed 1.
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@55d3336a.
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-05-18 02:45:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Any help interpreting what this is saying would be much appreciated.

Jeremy.

rossko57 · May 18, 2019, 9:24am

They might want to see the last transaction before your ghost.
Likewise, the later ghostly-off.

Always dims to 75% it appears - not random, internal default maybe?
And the 39 minutes makes another appearance.

Thedannymullen · May 18, 2019, 12:43pm

Does your switch have a good wall connection. I had some ghost switches on my insteon. I believe the wire nuts may have been loose. The keypad reset cause a few false switch events. Only thing I could come up with.

I redid the connection and problem seems to have gone away.

jlemmer · May 22, 2019, 3:39pm

Have you tried to reboot your openHAB server already? I face the same situation with one light in my house after my openHAB server has not been rebootet for several weeks/some months. I had no time yet to really get into it. But everything I checked so far, did not bring me closer to a solution. But I noticed that the ghost in my house goes on vacation for a longer time whenever I have to reboot my server.

jeremyjjr · July 22, 2019, 11:56am

Thanks all - sorry for delayed response. After a lot of testing, I finally identified that the problem was nothing to do with OH2 at all! I disconnected all channels, items and things, then removed the zWave device (Fibaro dimmer) from the zWave network. Still the problem carried on. Put this down to a faulty device and have replaced.

J.

Andrew_Rowe · July 25, 2019, 5:11pm

ghost confirmed!