Z-wave lock not deleting user codes

clark · July 23, 2023, 4:47pm

Openhab 4.0.0.M4
Windows 11
Intel PC

I have had problems with a z-wave lock for a long time

This is a YALE YRD256 lock which I originally controlled through Smartthings with no problem, but Smartthings did not give me the option of scheduling user code addition and deletion so I decided to move it to Openhab

I deleted all codes from the lock.
Now from Openhab I can add codes from the GUI but I cannot delete them, I also see a lot of PENDING that never go away

This is what I see in the event log when I add or delete a code

2023-07-23 11:36:36.683 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=usercode_code_3, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=usercode_code_5, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=usercode_code_1, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=usercode_code_2, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]

and this in the openhab log when I tried to delete a code

2023-07-23 11:36:36.679 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Value format error processing user code null
2023-07-23 11:36:36.681 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@5838cfde' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null

I can lock and unlock from Openhab I just cannot manage the user codes

Any ideas ?
Thank you

clark · July 24, 2023, 11:27pm

I upgraded to 4.0.0 stable and same issue.

Add a code

2023-07-24 18:14:48.330 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=usercode_code_5, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]


2023-07-24 18:15:56.267 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=usercode_code_6, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]

Delete a code by clicking on the x

The error seems to be saying that the user code is empty, but I am trying to delete a user code so the field should be empty

2023-07-24 18:17:24.915 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Value format error processing user code null
2023-07-24 18:17:24.917 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null

or

2023-07-24 18:08:12.411 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Value format error processing user code null
2023-07-24 18:08:12.413 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: Cannot invoke "Object.getClass()" because "value" is null
	at org.openhab.core.config.core.ConfigUtil.normalizeType(ConfigUtil.java:191) ~[?:?]
	at org.openhab.core.config.core.ConfigUtil.normalizeTypes(ConfigUtil.java:228) ~[?:?]
	at org.openhab.core.thing.internal.ThingManagerImpl.normalizeConfiguration(ThingManagerImpl.java:701) ~[?:?]
	at org.openhab.core.thing.internal.ThingManagerImpl.normalizeThingConfiguration(ThingManagerImpl.java:666) ~[?:?]
	at org.openhab.core.thing.internal.ThingManagerImpl.thingUpdated(ThingManagerImpl.java:413) ~[?:?]
	at org.openhab.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:234) ~[?:?]
	at org.openhab.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:145) ~[?:?]
	at org.openhab.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:1) ~[?:?]
	at org.openhab.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:322) ~[?:?]
	at org.openhab.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:1) ~[?:?]
	at org.openhab.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:66) ~[?:?]
	at org.openhab.core.common.registry.AbstractProvider.notifyListenersAboutUpdatedElement(AbstractProvider.java:91) ~[?:?]
	at org.openhab.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:118) ~[?:?]
	at org.openhab.core.thing.internal.ThingManagerImpl.thingUpdated(ThingManagerImpl.java:248) ~[?:?]
	at org.openhab.core.thing.internal.ThingHandlerCallbackImpl.thingUpdated(ThingHandlerCallbackImpl.java:150) ~[?:?]
	at org.openhab.core.thing.binding.BaseThingHandler.updateConfiguration(BaseThingHandler.java:498) ~[?:?]
	at org.openhab.core.thing.binding.ConfigStatusThingHandler.updateConfiguration(ConfigStatusThingHandler.java:73) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleConfigurationUpdate(ZWaveThingHandler.java:1059) ~[?:?]
	at org.openhab.core.thing.internal.ThingRegistryImpl.updateConfiguration(ThingRegistryImpl.java:94) ~[?:?]
	at org.openhab.core.io.rest.core.internal.thing.ThingResource.updateConfiguration(ThingResource.java:542) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
	at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.4.5]
	at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.4.5]
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.4.5]
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.4.5]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:234) ~[bundleFile:3.4.5]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:520) ~[bundleFile:4.0.4]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5]
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.50.v20221201]
	at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:100) ~[bundleFile:?]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:310) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.50.v20221201]
	at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.50.v20221201]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]

Can anyone shed some light on why I cannot delete codes?

Thank you

apella12 · July 24, 2023, 11:50pm

Assuming the lock was discovered securely with the zstick in your PC and there is a 16 byte string is on the advanced tab for the controller, I would set the binding in debug mode and try to set and delete a code. As the device is “listening” there really should not be any “pending” message, except maybe very briefly. My guess at this point is that it is not fully discovered securely, but could be wrong.

clark · July 25, 2023, 12:20am

Yes, I can see the 16 byte string in the controller.

The locks, I have 3, all show secure inclusion

    zwave_neighbours
    4,5,8,11,12,13,22,23,25,32,34,36,37,51
    zwave_manufacturer
    297
    zwave_listening
    false
    zwave_class_basic
    BASIC_TYPE_ROUTING_SLAVE
    zwave_class_generic
    GENERIC_TYPE_ENTRY_CONTROL
    zwave_plus_roletype
    ROLE_TYPE_SLAVE_SLEEPING_LISTENING
    zwave_nodeid
    62
    zwave_version
    1.80
    zwave_plus_devicetype
    NODE_TYPE_ZWAVEPLUS_NODE
    zwave_class_specific
    SPECIFIC_TYPE_SECURE_KEYPAD_DOOR_LOCK
    defaultAssociations
    1
    dbReference
    594
    modelId
    YRD256
    zwave_routing
    true
    manufacturerId
    0129
    vendor
    ASSA ABLOY
    zwave_lastheal
    2023-07-24T09:11:13Z
    zwave_frequent
    true
    zwave_secure
    true
    zwave_devicetype
    32770
    zwave_beaming
    true
    manufacturerRef
    8002:0600,8109:0DD5
    zwave_deviceid
    1536

After playing for a while they all show the pending warning and all I get is this when adding a code, nothing when trying to delete a code

2023-07-24 19:12:49.179 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=usercode_code_5, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]

apella12 · July 25, 2023, 11:57am

And the debug level during the operations?

clark · July 25, 2023, 12:08pm

I set it to TRACE

apella12 · July 25, 2023, 1:25pm

Not needed and too much. The developer has concentrated everything at the Debug level. There is a tool to read the output (but it ignores trace) Z-Wave Log Viewer (opensmarthouse.org)

clark · July 25, 2023, 2:28pm

The Z-wave log viewer does not show anything maybe because there is no node associated with the message, but if I look at the openhab log I see this at the time I am trying to delete codes

2023-07-25 09:09:13.691 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null
2023-07-25 09:09:16.646 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null
2023-07-25 09:09:27.344 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null
2023-07-25 09:21:56.260 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Value format error processing user code null
2023-07-25 09:21:56.263 [ERROR] [ore.thing.internal.ThingRegistryImpl] - Could not inform the ThingTracker 'org.openhab.core.thing.internal.ThingManagerImpl@195dbf23' about the 'THING_UPDATED' event!
java.lang.NullPointerException: null

apella12 · July 25, 2023, 6:25pm

I don’t have the lock and can’t tell anything from the posted logs. My guess is that the actual problem is the codes are not being added in the first place. That’s what the “pending” means to me. Therefore, trying to delete what was not added is causing the NPE.

Normally with a sleeping device, the pending can be removed by waking it, but the lock should be frequently listening, so that should not be needed. Also, your issue would suggest a communication issue, but it looks like the device has plenty of neighbors and you can operate from OH, so that is not likely it either.

Sorry
I’ll ping @chris for other ideas, but he hasn’t been around lately.

apella12 · July 26, 2023, 6:41pm

I did think of one more thing, just to get some information. Try a debug log while operating (open/close) the lock from OH. It might provide a clue to the user code issues (or not).

clark · July 26, 2023, 10:27pm

I don’t think that helps at all

The events log shows

2023-07-26 17:12:57.794 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Deck_Door' received command OFF
2023-07-26 17:12:57.795 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Deck_Door' predicted to become OFF
2023-07-26 17:12:57.795 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Deck_Door' changed from ON to OFF

2023-07-26 17:14:33.585 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Deck_Door' received command ON
2023-07-26 17:14:33.586 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Deck_Door' predicted to become ON
2023-07-26 17:14:33.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Deck_Door' changed from OFF to ON

2023-07-26 17:23:08.904 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Mud_Room_lock' changed from NULL to OFF
2023-07-26 17:23:15.176 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Mud_Room_lock' received command ON
2023-07-26 17:23:15.176 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Mud_Room_lock' predicted to become ON
2023-07-26 17:23:15.176 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Mud_Room_lock' changed from OFF to ON

There is nothing in the Openhab log except

2023-07-26 17:26:02.390 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Mud_Room_lock' to rrd4j database: Bad sample time: 1690410360. Last update time was 1690410360, at least one second step is required

clark · July 27, 2023, 2:05pm

Thanks for your suggestions. I am also seeing a phantom item linked to a zwave node that does not exist anymore. I am seriously considering resetting the zwave controller and rebuilding the zwave network from scratch, a bit of work but maybe more productive in the long run

Thanks again
Carlos

apella12 · July 27, 2023, 7:29pm

No worries. In my experience the zwave log levels higher than INFO might alert you to a problem, but do not help to find a solution. Like an iceberg, 90% is below the surface. That is why that debug viewer exists.

If you have a phantom node see this:
Z-Wave Zombies.pdf (571.9 KB)

You can also remove orphan links using the karaf console (openhab-cli console)
openhab> openhab:links orphan list then purge

clark · September 7, 2023, 11:34pm

Hi:

I just wanted to give you an update since you helped me quite a bit.
After struggling for some time and not making any progress, I moved openhab from Windows to linux (for other reasons) and took the opportunity to move the zwave network to zwavejs2mqtt.
After doing that everything started working, I can add and delete codes in the locks from zwavejs and from Openhab. It’s a bit more work to enter all the mqtt topics but in the end it is worth it to have a reliable system

Thanks again

Carlos

apella12 · September 8, 2023, 12:13am

Glad everything is working. Thanks for the update. Coincidentally (also for other reasons) I’m also using zwave-js-ui as the ZWave interface to OH. Agree the generic Mqtt was a lot of work as I have 135 channels, but can do everything I was doing before. The HA configurations are problematic.