- OpenHab 2.3 on Raspberry Pi 3
So I’m another poor sap trying to get this Schlage Connect Lock working with Openhab.
I managed to successfully complete the installation of the snapshot Zwave finding as per:
https://community.openhab.org/t/how-to-upgrade-zwave-binding-to-latest-snapshot/23268/49
I’m pretty sure I’ve got the right binding running… when I check it I get this:
openhab> bundle:list | grep ZWave
250 │ Active │ 80 │ 2.3.0.201806262322 │ ZWave Binding
Before upgrading to the snapshot binding, the lock was excluded on the network map, doing this got me as far as showing a connection between the lock and the Z-Stick.
Then, after quite a bit of fighting for signal, managed to get HabMin to find the deadbolt and add it.
This is where the confusion starts. The exact order of operations to do this is a bit unclear. In the documentation for the lock it instructs to put in the 6-didget pin to put it in pairing mode, but I’m not exactly sure when. I’ve been going with:
- Scan for Zwave devices using Habmin
- Let Lock show up in inbox (AS the lock, delete if it shows up as “Node 6, unknown device”
- Add Lock
- Enter PIN on lock to put in pairing mode.
Or variations thereof. In the logs I’m not quite sure what I’m looking at, but I’m think I’m seeing a lot of indications that the lock isn’t talking much. Of interest also is that Habmin had a RED popup which I’m pretty sure read “Secure Initialization Failed”, but I didn’t see it repeated in the log. This popup happened at the moment the Lock arrived in the inbox as a lock (As opposed to an unknown device.
I’m left with a lock that’s been added as a “thing” but doesn’t work. When I go to open it I get this in the log:
2018-12-03 00:27:45.307 [WARN ] [nal.converter.ZWaveDoorLockConverter] - NODE 6: Command class COMMAND_CLASS_DOOR_LOCK not found
2018-12-03 00:27:45.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: No messages returned from converter
2018-12-03 00:27:46.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:512:node6:lock_door --> OFF
2018-12-03 00:27:46.162 [WARN ] [nal.converter.ZWaveDoorLockConverter] - NODE 6: Command class COMMAND_CLASS_DOOR_LOCK not found
2018-12-03 00:27:46.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: No messages returned from converter
Am I pairing wrong? Am I using the wrong binding still? Do I need to have the lock pin entered when the zstick listens for it? . I’ve been reading all kinds threads about “including/excluding” zwave devices and I’m getting pretty burried here, hoping the answer is a little more simple than that.
Here are my logs during pairing. As always, any help provided is greatly appreciated.
2018-12-03 00:10:36.228 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=406, service.bundleid=250, service.scope=singleton} - org.openhab.binding.zwave
2018-12-03 00:10:36.262 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node6.
2018-12-03 00:10:36.273 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller status changed to ONLINE.
2018-12-03 00:10:36.276 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller is ONLINE. Starting device initialisation.
2018-12-03 00:10:36.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:lock_door linked - polling started.
2018-12-03 00:10:36.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:alarm_raw linked - polling started.
2018-12-03 00:10:36.297 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:battery-level linked - polling started.
2018-12-03 00:10:36.381 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties.
2018-12-03 00:10:36.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties. MAN=59
2018-12-03 00:10:36.496 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties. MAN=59. SET. Was 59
2018-12-03 00:10:36.500 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Properties synchronised
2018-12-03 00:10:36.949 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-03 00:10:36.951 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising Thing Node...
2018-12-03 00:10:36.953 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising cmd channel zwave:device:512:node6:lock_door for OnOffType
2018-12-03 00:10:36.955 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising state channel zwave:device:512:node6:lock_door for OnOffType
2018-12-03 00:10:36.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising cmd channel zwave:device:512:node6:alarm_raw for StringType
2018-12-03 00:10:36.959 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising state channel zwave:device:512:node6:alarm_raw for StringType
2018-12-03 00:10:36.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising cmd channel zwave:device:512:node6:battery-level for PercentType
2018-12-03 00:10:36.962 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising state channel zwave:device:512:node6:battery-level for PercentType
2018-12-03 00:10:36.964 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling intialised at 1800 seconds - start in 248400 milliseconds.
2018-12-03 00:10:36.965 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Device initialisation complete.
2018-12-03 00:10:37.362 [ERROR] [e.internal.WriterInterceptorExecutor] - MessageBodyWriter not found for media type=text/plain, type=class java.util.Collections$UnmodifiableCollection, genericType=class java.util.Collections$UnmodifiableCollection.
2018-12-03 00:11:34.773 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2018-12-03 00:11:34.781 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 49 84 06 08 04 40 03 22 72 7A 98 86 41
2018-12-03 00:11:34.784 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 0E 00 49 84 06 08 04 40 03 22 72 7A 98 86 41
2018-12-03 00:11:34.786 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 65
2018-12-03 00:11:34.788 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2018-12-03 00:11:34.792 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 6: Message payload = 84 06 08 04 40 03 22 72 7A 98 86
2018-12-03 00:11:34.800 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2018-12-03 00:11:34.804 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2018-12-03 00:11:34.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=6, callback=132, payload=84 06 08 04 40 03 22 72 7A 98 86
2018-12-03 00:11:34.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationUpdate[73], type=Request[0], dest=6, callback=132, payload=84 06 08 04 40 03 22 72 7A 98 86
2018-12-03 00:11:34.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=6, callback=132, payload=84 06 08 04 40 03 22 72 7A 98 86
2018-12-03 00:11:34.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-03 00:11:34.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-03 00:11:34.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-03 00:11:34.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
2018-12-03 00:11:34.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=6, callback=132, payload=84 06 08 04 40 03 22 72 7A 98 86
2018-12-03 00:11:34.827 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2018-12-03 00:11:34.829 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 6: Application update request. Node information received. Transaction null
2018-12-03 00:11:34.831 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false
2018-12-03 00:11:34.833 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 6: Application update request. Requesting node state.
2018-12-03 00:11:34.835 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2018-12-03 00:11:34.837 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2018-12-03 00:11:34.840 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling intialised at 1800 seconds - start in 75 milliseconds.
2018-12-03 00:11:34.842 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 6: Application update - no transaction.
2018-12-03 00:11:34.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-03 00:11:34.846 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-12-03 00:11:34.848 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2018-12-03 00:11:34.850 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2018-12-03 00:11:34.915 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
2018-12-03 00:11:34.917 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:512:node6:lock_door
2018-12-03 00:11:34.919 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:512:node6:alarm_raw
2018-12-03 00:11:34.922 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:512:node6:battery-level
2018-12-03 00:11:35.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Node is listening - ignore wakeup```