Z-Wave binding gives "No endpoint 2!" debug log for Merten wall switch

daniel_digeraas · August 25, 2019, 1:19pm

Hello
I have five schneider/merten “506219 Battery Powered Wall Controller”. They are very finicky to get working but integrates nicely with other buttons on the wall. After updating to 2.5.0-M2 I can’t get them to work anymore.

What I have done so far:

Followed the remove all things, reinstall the binding and then add them again steps
Hacked the org.eclipse.smarthome.core.thing.Thing.json file and manually added four channels that should map to COMMAND_CLASS_BASIC:x where x is 1 to 4.
Cloned the binding repo from github, patched the 506219_0_0.xml thing file, built and loaded into the openhab installation.

What I get (when pressing random button 2):

2019-08-25 15:02:17.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:VERSION)
2019-08-25 15:02:17.579 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 15:02:17.580 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!

I’m reading source at this point. Do anyone know why the channels aren’t registering correctly? If/when the problem gets solved, how can I send my findings upstream so other could use these switches in the future?

chris · August 25, 2019, 1:29pm

This will mean that the binding has not found endpoint 2 during the interrogation phase of the initialisation. I also note that the database only has a single endpoint (ie the root) registered, so things are clearly not well defined here.

Well, if you’re heading off-piste, then it’s going to be more difficult to help you here. I’m not completely sure how you have done this so I’d recommend getting the switch working before manually hacking the configuration.

daniel_digeraas · August 25, 2019, 1:51pm

Thanks for the response. In the beginning I included the switches with z-way. I have since moved from a raspberry pi to a x86 based embedded system and the z-way package don’t want to be installed on that machine. Is there some way of forcing an interview with a specific device through openhab?

The switches did work before the update from 2.2 to 2.5-M2. I have not excluded and reincluded them.

I should clarify that I was able to add the switch thing with my SNAPSHOT version with custom thing definition and got the correct channels. When I press a button on the remote, the same error message pops up though.

Regarding the XML-fine, it’s not just incomplete but straight out wrong when it comes to configuration. I blame Merten for that because they have misleading documentation. When I have something working I will consider updating the the database.

Snippet of my xml change:

<channels>
...
      <channel id="switch_binary1" typeId="switch_binary">
        <label>Switch</label>
        <properties>
          <property name="binding:*:OnOffType">COMMAND_CLASS_BASIC:1</property>
        </properties>
      </channel>
...

chris · August 25, 2019, 1:56pm

openHAB will automatically perform the interrogation if it doesn’t already have all the information it needs. If this fails, you can select the Reinitialise device option in the thing parameters. Or, you can remove the XML file from the {userdata/zwave} folder for the node in question.

Can you please post the XML file that OH has generated for this device so I can see what the device interrogation found.

daniel_digeraas · August 25, 2019, 2:13pm

The XML-file for node 12 (my switch) isn’t there. It wasn’t there previously either. My conclusion is that these remotes never where properly interrogated and before the rewrite of the z-wave binding it did things differently. I will try to reinclude them and if everything else fails, brute force a node 12 XML file and try with that.

The switch is the type that is battery powered and very finicky and it won’t surprise me the least if it have limped along until now.

@chris When I have your attention, how do I go about pushing the thing XML file changes upstream so that other at least wont have that problem in the future?

chris · August 25, 2019, 2:17pm

I would suggest to get a log of the initialisation. Re-including probably won’t make any difference as the interrogation isn’t linked to inclusion at all.

You’d need to make the changes directly in the database using the online editor.

https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-database-guide

daniel_digeraas · August 25, 2019, 2:28pm

The log output filtered on NODE 12 from start of openhab. Includes me waking the device up in different ways


2019-08-25 16:21:44.661 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:337a9e07:node12:switch_binary1 linked - polling started.
2019-08-25 16:21:44.668 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:337a9e07:node12:switch_binary2 linked - polling started.
2019-08-25 16:21:44.668 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:337a9e07:node12:switch_binary3 linked - polling started.
2019-08-25 16:21:44.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:337a9e07:node12:switch_binary4 linked - polling started.
2019-08-25 16:21:47.671 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2019-08-25 16:21:47.748 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Init node thread start
2019-08-25 16:21:48.184 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 12: Serializing from file /var/lib/openhab2/zwave/network_c571576d__node_12.xml
2019-08-25 16:21:48.185 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 12: Error serializing from file: file does not exist.
2019-08-25 16:21:48.384 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Starting initialisation from EMPTYNODE
2019-08-25 16:21:48.420 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Init node thread finished
2019-08-25 16:21:48.438 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to IDENTIFY_NODE
2019-08-25 16:21:48.439 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: Initialisation starting
2019-08-25 16:21:48.911 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: ProtocolInfo
2019-08-25 16:21:48.911 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Listening = false
2019-08-25 16:21:48.912 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Routing   = false
2019-08-25 16:21:48.912 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Beaming   = false
2019-08-25 16:21:48.913 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Version   = 3
2019-08-25 16:21:48.913 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: FLIRS     = false
2019-08-25 16:21:48.914 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Security  = false
2019-08-25 16:21:48.914 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Max Baud  = 9600
2019-08-25 16:21:48.915 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Basic    = BASIC_TYPE_CONTROLLER
2019-08-25 16:21:48.916 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Generic  = GENERIC_TYPE_SWITCH_REMOTE
2019-08-25 16:21:48.916 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Specific = SPECIFIC_TYPE_NOT_USED
2019-08-25 16:21:48.917 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2019-08-25 16:21:48.927 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2019-08-25 16:21:48.928 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Version = 1, version set. Enabling extra functionality.
2019-08-25 16:21:48.929 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2019-08-25 16:21:48.929 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_BASIC
2019-08-25 16:21:48.930 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2019-08-25 16:21:48.941 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2019-08-25 16:21:48.951 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@62a6099c
2019-08-25 16:21:48.952 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init transaction completed with response COMPLETE
2019-08-25 16:21:48.952 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to REQUEST_NIF
2019-08-25 16:21:48.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@27a49bac
2019-08-25 16:21:48.954 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 26 priority from Controller to Immediate
2019-08-25 16:21:48.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-08-25 16:21:48.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 26 to queue - size 2
2019-08-25 16:21:51.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to ONLINE.
2019-08-25 16:21:51.188 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is ONLINE. Starting device initialisation.
2019-08-25 16:21:51.191 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties.
2019-08-25 16:21:51.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=2147483647
2019-08-25 16:21:51.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Properties synchronised
2019-08-25 16:21:51.213 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising Thing Node...
2019-08-25 16:21:51.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:337a9e07:node12:basic_switch_binary for OnOffType
2019-08-25 16:21:51.215 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:337a9e07:node12:basic_switch_binary for OnOffType
2019-08-25 16:21:51.215 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:337a9e07:node12:switch_binary1 for OnOffType
2019-08-25 16:21:51.216 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:337a9e07:node12:switch_binary1 for OnOffType
2019-08-25 16:21:51.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:337a9e07:node12:switch_binary2 for OnOffType
2019-08-25 16:21:51.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:337a9e07:node12:switch_binary2 for OnOffType
2019-08-25 16:21:51.218 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:337a9e07:node12:switch_binary3 for OnOffType
2019-08-25 16:21:51.218 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:337a9e07:node12:switch_binary3 for OnOffType
2019-08-25 16:21:51.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:337a9e07:node12:switch_binary4 for OnOffType
2019-08-25 16:21:51.220 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:337a9e07:node12:switch_binary4 for OnOffType
2019-08-25 16:21:51.220 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 86400 seconds - start in 28944000 milliseconds.
2019-08-25 16:21:51.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Device initialisation complete.
2019-08-25 16:22:48.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:22:48.213 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:22:48.213 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command class COMMAND_CLASS_MULTI_CHANNEL not found, trying to add it.
2019-08-25 16:22:48.214 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:22:48.214 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_MULTI_CHANNEL, endpoint 0 created
2019-08-25 16:22:48.215 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_MULTI_CHANNEL to endpoint 0
2019-08-25 16:22:48.215 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:22:48.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:22:48.299 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:22:48.299 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:22:54.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:22:54.655 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:22:54.656 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:22:54.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:22:54.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:22:54.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:01.384 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null
2019-08-25 16:23:01.385 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_MANUFACTURER_SPECIFIC
2019-08-25 16:23:01.386 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created
2019-08-25 16:23:01.386 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC.
2019-08-25 16:23:01.387 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC to the list of supported command classes.
2019-08-25 16:23:01.387 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_VERSION
2019-08-25 16:23:01.388 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_VERSION, endpoint 0 created
2019-08-25 16:23:01.389 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_VERSION.
2019-08-25 16:23:01.390 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_VERSION to the list of supported command classes.
2019-08-25 16:23:01.390 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_CONFIGURATION
2019-08-25 16:23:01.391 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created
2019-08-25 16:23:01.391 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_CONFIGURATION.
2019-08-25 16:23:01.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_CONFIGURATION to the list of supported command classes.
2019-08-25 16:23:01.392 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_ASSOCIATION
2019-08-25 16:23:01.393 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created
2019-08-25 16:23:01.394 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_ASSOCIATION.
2019-08-25 16:23:01.394 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_ASSOCIATION to the list of supported command classes.
2019-08-25 16:23:01.394 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-08-25 16:23:01.395 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created
2019-08-25 16:23:01.395 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION.
2019-08-25 16:23:01.395 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION to the list of supported command classes.
2019-08-25 16:23:01.396 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL
2019-08-25 16:23:01.396 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created
2019-08-25 16:23:01.396 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_SWITCH_MULTILEVEL.
2019-08-25 16:23:01.397 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.
2019-08-25 16:23:01.397 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_BASIC_WINDOW_COVERING
2019-08-25 16:23:01.397 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_BASIC_WINDOW_COVERING, endpoint 0 created
2019-08-25 16:23:01.398 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update is adding command class COMMAND_CLASS_BASIC_WINDOW_COVERING.
2019-08-25 16:23:01.398 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_BASIC_WINDOW_COVERING to the list of supported command classes.
2019-08-25 16:23:01.398 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction.
2019-08-25 16:23:01.652 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 1 messages in the queue
2019-08-25 16:23:01.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: COMMAND_CLASS_WAKE_UP not found - setting AWAKE
2019-08-25 16:23:01.654 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms
2019-08-25 16:23:01.654 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-25 16:23:01.675 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE
2019-08-25 16:23:04.156 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-08-25 16:23:06.656 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-08-25 16:23:06.657 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No more messages, go back to sleep
2019-08-25 16:23:13.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:23:13.152 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:13.152 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:18.633 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null
2019-08-25 16:23:18.633 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction.
2019-08-25 16:23:18.885 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 1 messages in the queue
2019-08-25 16:23:18.886 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: COMMAND_CLASS_WAKE_UP not found - setting AWAKE
2019-08-25 16:23:18.887 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms
2019-08-25 16:23:18.887 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-25 16:23:18.896 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE
2019-08-25 16:23:21.388 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-08-25 16:23:23.888 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-08-25 16:23:23.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No more messages, go back to sleep
2019-08-25 16:23:25.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:23:25.804 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:25.805 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:25.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:REQUEST_NIF)
2019-08-25 16:23:25.970 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:25.970 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:29.925 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null
2019-08-25 16:23:29.926 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction.
2019-08-25 16:23:30.179 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 1 messages in the queue
2019-08-25 16:23:30.180 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: COMMAND_CLASS_WAKE_UP not found - setting AWAKE
2019-08-25 16:23:30.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms
2019-08-25 16:23:30.181 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-25 16:23:30.187 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE
2019-08-25 16:23:30.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 26: Transaction not completed
2019-08-25 16:23:30.409 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction TID 26: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0
2019-08-25 16:23:30.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Response processed after 120ms
2019-08-25 16:23:30.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 26: Transaction completed
2019-08-25 16:23:30.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:26 DONE
2019-08-25 16:23:30.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-25 16:23:30.413 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@3c76c4b6
2019-08-25 16:23:30.414 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init transaction completed with response COMPLETE
2019-08-25 16:23:30.414 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to SECURITY_REPORT
2019-08-25 16:23:30.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-08-25 16:23:30.416 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: SECURE command class not supported
2019-08-25 16:23:30.417 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to MANUFACTURER
2019-08-25 16:23:30.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-08-25 16:23:30.418 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: MANUFACTURER - send ManufacturerSpecific
2019-08-25 16:23:30.419 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 12: Creating new message for command MANUFACTURER_SPECIFIC_GET
2019-08-25 16:23:30.420 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: ZWaveCommandClassTransactionPayload - send to node
2019-08-25 16:23:30.421 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2019-08-25 16:23:30.421 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MANUFACTURER_SPECIFIC is NOT required to be secured
2019-08-25 16:23:30.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@478b64e3
2019-08-25 16:23:30.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 117 priority from Config to Immediate
2019-08-25 16:23:30.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-08-25 16:23:30.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 117 to queue - size 50
2019-08-25 16:23:32.682 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state MANUFACTURER
2019-08-25 16:23:35.183 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state MANUFACTURER
2019-08-25 16:23:35.183 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No more messages, go back to sleep
2019-08-25 16:23:36.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:36.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:36.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:36.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:36.341 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:36.342 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:40.557 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null
2019-08-25 16:23:40.558 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction.
2019-08-25 16:23:40.809 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 1 messages in the queue
2019-08-25 16:23:40.810 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: COMMAND_CLASS_WAKE_UP not found - setting AWAKE
2019-08-25 16:23:40.810 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms
2019-08-25 16:23:40.811 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-25 16:23:40.814 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE
2019-08-25 16:23:43.311 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state MANUFACTURER
2019-08-25 16:23:44.866 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 09 00 13 0C 02 72 04 25 0C B4 
2019-08-25 16:23:44.892 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-08-25 16:23:44.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 117: Transaction not completed
2019-08-25 16:23:45.525 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 12, Status = Transmission complete, no ACK received(1)
2019-08-25 16:23:45.527 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-25 16:23:45.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Transaction failed waiting for REQUEST, assume sleeping device.
2019-08-25 16:23:45.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: CANCEL while sending message. Requeueing - 2 attempts left!
2019-08-25 16:23:45.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-08-25 16:23:45.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 117 to queue - size 52
2019-08-25 16:23:45.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 117: Transaction not completed
2019-08-25 16:23:53.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:53.338 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:53.338 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:55.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:55.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:55.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:55.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:55.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:55.093 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:56.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:56.813 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:56.814 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:23:56.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:MANUFACTURER)
2019-08-25 16:23:56.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-08-25 16:23:56.890 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No endpoint 2!
2019-08-25 16:24:01.985 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null
2019-08-25 16:24:01.985 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction.
2019-08-25 16:24:02.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 1 messages in the queue
2019-08-25 16:24:02.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: COMMAND_CLASS_WAKE_UP not found - setting AWAKE
2019-08-25 16:24:02.238 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms
2019-08-25 16:24:02.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-25 16:24:02.241 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE
2019-08-25 16:24:04.738 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 1 Messages waiting, state MANUFACTURER
2019-08-25 16:24:06.404 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 09 00 13 0C 02 72 04 25 0D B5 
2019-08-25 16:24:06.416 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-08-25 16:24:06.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 117: Transaction not completed
2019-08-25 16:24:06.823 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 13, Status = Transmission complete, no ACK received(1)
2019-08-25 16:24:06.824 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-25 16:24:06.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Transaction failed waiting for REQUEST, assume sleeping device.
2019-08-25 16:24:06.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: CANCEL while sending message. Requeueing - 1 attempts left!
2019-08-25 16:24:06.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-08-25 16:24:06.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 117 to queue - size 51
2019-08-25 16:24:06.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 117: Transaction not completed

chris · August 25, 2019, 2:30pm

Please don’t filter the log as it removes all the good stuff that I need in order to see what is happening.

daniel_digeraas · August 25, 2019, 2:48pm

The log file is 1 MB in size, and that is 2 minutes of running openhab with debug logging. (I have approx 45 devices in my network). I can see if I can make openhab send zwave logs to a separate file unless you are OK with me sharing it by other means (ex. dropbox).

Trivia: I have 181MB of openhab logs.

chris · August 25, 2019, 2:53pm

Sure - that’s absolutely fine. Thanks.

daniel_digeraas · August 25, 2019, 2:55pm

This is start and a couple of button presses. If there are some thing you want me doing and log. Let me know.

chris · August 25, 2019, 3:10pm

I think in the first instance you need to wake up the device again as the binding is waiting. I recall these devices in the past - they don’t support the WAKEUP command class, but the binding will think they are awake when they receive the NIF - something you press must do this as I see this in the log, and the binding sends a request to the device, and it gets a response.

I would try and work out how to get the NIF sent then press this a lot of times over the period of a minute or two.

Things slow down as the binding moves on to other devices in the meantime, so it requires a repeat of the wakeup.

daniel_digeraas · August 25, 2019, 3:16pm

Thanks alot! I will try that and report back with results. I do have other things to attend to so we see when I can continue.

daniel_digeraas · August 25, 2019, 8:03pm

Just a quick update before I go to bed:
I can with lots of button pushing get the remote to progress a bit further in the initialization. I seem to get stuck at state ENDPOINTS though.

My theory is that the binding is to slow to send out the packages and thus the remote goes to sleep again. The window of transmission is very narrow. This is however theory that might turn out to be incorrect. I’m sifting through the code trying to understand the flow and see if I can proof or disproof my theory.

chris · August 25, 2019, 8:24pm

Can you provide an updated debug log and I’ll take a look?

daniel_digeraas · August 26, 2019, 4:00am

I will produce the logs this evening after work.

daniel_digeraas · August 26, 2019, 1:33pm

I have produced some logs from startup to the point the binding is trying to determine endpoints. There should be some good nuggets in there hopefully. Note, this is a custom build from latest master branch with sleep timeout changed from 5000ms to 9000ms in ZWaveNode.

I’m sorry for the large and chatty log file, but that’s what happens when you z-wave everything in your house

Bruce_Osborne · August 26, 2019, 2:05pm

The log viewer helps sort things out.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

daniel_digeraas · August 26, 2019, 2:31pm

Thanks! That helps.

daniel_digeraas · August 27, 2019, 3:34pm

So, I have some good and some bad news. The good news: I have “solved” the switch not working. The bad news: It involves going off-piste as @chris so aptly did put it.

The problem with the Merten/Scheider Wall Mounted Z-Wave Switches are that they are awake really short time and timing must be right if one is to set parameters or do anything. Because of this, the zwave binding have a really hard time interrogating the device. I have not been able to fully interrogate the device through conventional means. However, when the binding have finished it’s interrogation of a device, it will store that data as a xml file under userdata/zwave (/var/lib/openhab2/zwave in my case) so that it don’t need to interrogate the device again.

I exploit this behavior by crafting my own xml file. Now, the file is incomplete and I don’t have any hope to change the parameters with it. But as I have had these remotes in the setup before and have setted the parameters as I want them, I don’t really care.

I will add the xml file if any brave souls want to follow my footsteps, but be warned! There be dragons! There are also absolutely no guarantees that my solution will hold through releases.

A final piece of advice: Stay away from Merten/Schneider CONNECT.

network_c571576d__node_12.xml (15.1 KB)

Thanks to @chris for all your help! Someday I might have more time to actually try to see if I can contribute with some code to fix this. I will follow up on the device definition though.

If anybody have questions please ask them in this topic and I will answer what I can…