Contact items switching from CLOSED to OPEN on their own

DocFraggle · January 6, 2017, 9:31pm

Hi all,

today I upgraded to the latest snapshot (from build #692 to #696). I’ve got some Vision Security contacts on my windows, after starting the new snapshot I noticed that all of the window contact-items in Basic UI were in state “OPEN” in Basic UI, but in fact they were all closed. At first I thought it’s maybe a glitch in the persistence after restarting, so I manually opened and closed all the windows, afterwards Basic UI showed CLOSED for all of them.
Some hours later I noticed that all of the contacts were in state OPEN again!

I set the zwave module to trace logging, opened and closed one of the windows to get the CLOSED state, and waited some minutes (of course without touching the contact or the window):

22:20:50.280 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
22:20:50.281 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 10 0A 71 05 06 00 00 FF 06 FE 00 00 84 
22:20:50.281 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 10 0A 71 05 06 00 00 FF 06 FE 00 00 84 
22:20:50.281 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x84
22:20:50.281 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
22:20:50.281 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 10 0A 71 05 06 00 00 FF 06 FE 00 00 
22:20:50.281 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
22:20:50.281 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT
22:20:50.281 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:20:50.282 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x84
22:20:50.282 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 10 0A 71 05 06 00 00 FF 06 FE 00 00 84 
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 10 0A 71 05 06 00 00 FF 06 FE 00 00 84 
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 10 0A 71 05 06 00 00 FF 06 FE 00 00 
22:20:50.282 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
22:20:50.282 [TRACE] [ssage.ApplicationCommandMessageClass] - Handle Message Application Command Request
22:20:50.282 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Application Command Request (ALIVE:DONE)
22:20:50.282 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Starting initialisation from DONE
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@8b31096 already registered
22:20:50.282 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Incoming command class ALARM
22:20:50.282 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 16: Found Command Class ALARM, passing to handleApplicationCommandRequest
22:20:50.282 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 16: Received ALARM command V4
22:20:50.282 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 16: Process NOTIFICATION_REPORT V4
22:20:50.282 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 16: NOTIFICATION report - 6 = 0, event=254, status=255
22:20:50.282 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 16: Alarm Type = ACCESS_CONTROL (6)
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
22:20:50.282 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveAlarmValueEvent
22:20:50.282 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = ALARM, value = 255
22:20:50.282 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
22:20:50.282 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
22:20:50.282 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 254, type OpenClosedType
22:20:50.282 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating channel state zwave:device:bb4d2b80:node16:sensor_door to OPEN [OpenClosedType]
22:20:50.282 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=16, callback=149, payload=10 05 71 04 00 06 00 
22:20:50.282 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 10 0A 71 05 06 00 00 FF 06 FE 00 00 
22:20:50.282 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=149, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
22:20:50.282 [TRACE] [ve.internal.protocol.ZWaveController] - Callback ID = 150
22:20:50.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
22:20:50.282 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
22:20:50.282 [TRACE] [ve.internal.protocol.ZWaveController] - Released. Transaction completed permit count -> 1
22:20:50.282 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 16: Response processed after 832ms/4898ms.
22:20:50.282 [TRACE] [ocol.ZWaveController$ZWaveSendThread] - Acquired. Transaction completed permit count -> 0
22:20:50.282 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
22:20:50.282 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xC6
22:20:50.283 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 10 02 80 02 25 96 C6 
22:20:50.283 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 09 00 13 10 02 80 02 25 96 C6 
22:20:50.283 [TRACE] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
22:20:50.283 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Buero_Sued changed from CLOSED to OPEN

As you can see the controller seems to receive an ALARM and updates the sensor_door channel state to OPEN.

Device type: ZD2102 Door Window Sensor

zwave_manufacturer 265
zwave_devicetype   8193

Any idea why that happens?

Regards, Christian

DocFraggle · January 6, 2017, 10:35pm

@chris: is it possible it has anything to do with your recent changes of ZWaveAlarmConverter.java?
Reverting to #692 fixes the problem.

Regards, Christian

adb76 · January 7, 2017, 8:16am

Same for me here. Yesterday I updated also from #692 to #696 and suddenly my Door Window Sensor ZD2102 changes from CLOSED to OPEN without “opening” the contact. Reverting back to #692 also solved the problem. If necessary I can also provide some debug logs.

Regards,
André

chris · January 7, 2017, 8:19am

Can you tell if it’s associated with polling? The change to the converter added the ability to filter events so if no filter is set then it shouldn’t change anything.

I’ll have a better look later tonight.

adb76 · January 7, 2017, 8:26am

I’m not sure if this answers your question:

My assumption is, that with the WAKE_UP of the Node it changes to the wrong status. In HABmin I see a polling period of 30 min and the wake up time is currently set to 60 min (for testing purposes). Please give me a hint if you need further information.

Thanks for your support.

chris · January 7, 2017, 1:06pm

Ok - I can see the issue. Event 254 has special meaning and this needs filtering out - I’ll try to update this tonight.

chris · January 7, 2017, 1:12pm

Let me know if this fixes the problem.

adb76 · January 7, 2017, 7:22pm

I’ve installed the build #698 from this afternoon where your change is included. So far this seems to fix it for me. Thank you!

chris · January 8, 2017, 3:07am

Great - thanks.

DocFraggle · January 8, 2017, 6:45am

Hi Chris, unfortunately now I’ve got the next problem: my persistence isn’t working, I didn’t have the time yet to figure out why. So after every restart the contacts have the state N/A. No problem so far, during the next wakeup cycle the zwave binding used to determine the state.
That’s not working any more… I restarted after your change yesterday (>9 hours), but the state is still N/A for all the contacts which I didn’t trigger manually…

Going back to #692 again fixes this:

07:44:06.092 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node17' changed from ONLINE to ONLINE: Node initialising: DETAILS
07:44:06.092 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node17' changed from ONLINE: Node initialising: DETAILS to ONLINE: Node initialising: GET_CONFIGURATION
07:44:06.093 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node17' changed from ONLINE: Node initialising: GET_CONFIGURATION to ONLINE: Node initialising: DYNAMIC_VALUES
07:44:06.280 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Buero_West_Batterie changed from NULL to 80
07:44:06.530 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Buero_West changed from NULL to CLOSED
07:44:07.032 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:bb4d2b80:node17' has been updated.

Christian

DocFraggle · January 8, 2017, 6:53am

I just found this in the log from this night, the battery value update works:

03:25:51.457 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: ASSOCIATIONS to ONLINE: Node initialising: SET_WAKEUP
03:25:51.457 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: SET_WAKEUP to ONLINE: Node initialising: SET_ASSOCIATION
03:25:51.457 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: SET_ASSOCIATION to ONLINE: Node initialising: DELETE_SUC_ROUTES
03:25:51.458 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: DELETE_SUC_ROUTES to ONLINE: Node initialising: SUC_ROUTE
03:25:51.458 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: SUC_ROUTE to ONLINE: Node initialising: STATIC_END
03:25:51.458 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: STATIC_END to ONLINE: Node initialising: SESSION_START
03:25:51.458 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: SESSION_START to ONLINE: Node initialising: GET_CONFIGURATION
03:25:51.854 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: GET_CONFIGURATION to ONLINE: Node initialising: DYNAMIC_VALUES
03:25:53.021 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Vorrat_Batterie changed from NULL to 100
03:25:53.704 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
03:25:53.704 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:bb4d2b80:node18' has been updated.
03:25:53.704 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: DYNAMIC_VALUES to ONLINE: Node initialising: DYNAMIC_END
03:25:53.705 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: DYNAMIC_END to ONLINE: Node initialising: HEAL_START
03:25:53.705 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: HEAL_START to ONLINE: Node initialising: DELETE_ROUTES
03:25:54.516 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: DELETE_ROUTES to ONLINE: Node initialising: RETURN_ROUTES
03:25:56.223 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: RETURN_ROUTES to ONLINE: Node initialising: NEIGHBORS
03:26:01.223 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Timeout while sending message. Requeueing - 2 attempts left!
03:26:01.229 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Initialising Thing Node...
03:26:01.229 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
03:26:01.229 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:bb4d2b80:node18' has been updated.
03:26:01.230 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node18' changed from ONLINE: Node initialising: NEIGHBORS to ONLINE
03:26:01.230 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Initialising Thing Node...
03:26:04.385 [WARN ] [l.serialmessage.SendDataMessageClass] - Node 255 not found!

So it’s only the contact state which isn’t working right now.

chris · January 8, 2017, 9:40am

Can you get a debug log please? I changed the way polling works if a recent version of the notification class is being used. This was to support new sensors like the motion sensor and the sensitive door sensor. Maybe it doesn’t work for all, or more likely we might need to change the cfg for some devices. It would be good to see the log though.

DocFraggle · January 8, 2017, 12:01pm

Hi Chris, this should be very detailed Noname6.xml (25.5 KB)

chris · January 8, 2017, 12:36pm

Thanks - can I ask you to get another log - same thing, just I want to see if this is repeated since this log looks a bit strange. The controller seems to reject the message, but the device acks the message, and then doesn’t respond…

Second question - what is the device?

chris · January 8, 2017, 12:59pm

In fact, a better question is “can you post the XML for this device” - I want to look at the versions of the command classes it’s using…

DocFraggle · January 8, 2017, 1:43pm

I’ll upload another log later this day, I reverted to 692.
Here’s the device’snode12.xml (9.4 KB)
xml

DocFraggle · January 8, 2017, 6:19pm

Hi Chris, I sent you an email with the log.

Christian

chris · January 9, 2017, 1:18pm

Thanks - what node am I looking at - node 18? If so, there’s not much in there for that node.

DocFraggle · January 10, 2017, 6:37am

Hi Chris,

I installed the latest binding version yesterday. It works, but it really takes forever to get the initial state of the contacts… openHAB is running for nearly 10 hours now, and it got only 8 out of the 10 contact’s states so far. This used to be one hour tops in the past.

Regards, Christian

DocFraggle · January 10, 2017, 12:09pm

One more issue I noticed: after starting openHAB with working persistence (Contact = CLOSED after startup), during the first wakeup cycle the contact switches from CLOSED to OPEN, and some milliseconds later from OPEN to CLOSED again.

11:18:13.673 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node11' changed from ONLINE to ONLINE: Node initialising: DETAILS
11:18:13.673 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node11' changed from ONLINE: Node initialising: DETAILS to ONLINE: Node initialising: GET_CONFIGURATION
11:18:13.674 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bb4d2b80:node11' changed from ONLINE: Node initialising: GET_CONFIGURATION to ONLINE: Node initialising: DYNAMIC_VALUES
11:18:14.501 [INFO ] [ome.event.GroupItemStateChangedEvent] - Windows changed from CLOSED to UNDEF through WS
11:18:14.502 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Wohnzimmer_Sued_links changed from CLOSED to OPEN
11:18:14.502 [INFO ] [ome.event.GroupItemStateChangedEvent] - WS changed from CLOSED to OPEN through Contact_Wohnzimmer_Sued_links
11:18:14.502 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'AlarmSwitch' received command ON
11:18:14.531 [INFO ] [eclipse.smarthome.model.script.Alarm] - Alarmanlage von Contact_Wohnzimmer_Sued_links getriggert!!!
11:18:14.961 [INFO ] [marthome.event.ItemStateChangedEvent] - Contact_Wohnzimmer_Sued_links changed from OPEN to CLOSED
11:18:14.961 [INFO ] [ome.event.GroupItemStateChangedEvent] - WS changed from OPEN to CLOSED through Contact_Wohnzimmer_Sued_links
11:18:14.961 [INFO ] [ome.event.GroupItemStateChangedEvent] - Windows changed from UNDEF to CLOSED through WS
11:18:15.396 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:bb4d2b80:node11' has been updated.

This triggers my alarm rule and all the alarm actions are executed…

...
when
    Item Contact_Wohnzimmer_Sued_links changed from CLOSED to OPEN
...