Motion sensor hsm100 fail to initialise

Avner · February 7, 2017, 5:37am

After copying the file homeseer_ezmotionexpress_0_0.xml into the latest snapshot, restarting openhab2, and intiialising the device, it shows up as EZMotion Express Wireless 3 in 1 Sensor, with 4 channels

Changing a parameter in Configuration Parameters e.g. On Time from 20 to e.g. 23 does not stick.
I tested the value change by setting a new value (23) via HABmin, manually waking up the device, and clicking Save. I then get a message Thing Saved Successfully, and a yellow icon pending near the field.

After refreshing the page, the new value shows up in HABmin without the yellow icon, and PaperUI shows the new value as well. Also the output log file indicates that the value is changed (snippet 1), But the new value doesn’t persist in the xml file, and the 4 channels are completely useless in PaperUI (img1)

img1

snippet 1

  80480:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:965  ] - NODE 20: Update CONFIGURATION 2/1 to 23
  80481:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:1428 ] - NODE 20: Config about to update 13 parameters...
  80482:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing group_org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup@30a3ce0b
  80483:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing wakeup_interval
  80484:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing group_1
  80485:2017-02-06 21:20:53.292 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_1_1
  80486:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_1_1 len=3
  80487:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_1_1 - id = '1'
  80488:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_2_1
  80489:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_2_1 len=3
  80490:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_2_1 - id = '2'
  80491:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1450 ] - NODE 20: Processing config_2_1 - size = '1'
  80492:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1473 ] - NODE 20: Sub-parameter config_2_1 is 00000017
  80493:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1475 ] - NODE 20: Pre-processing  00000017>>FFFFFFFF
  80494:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1488 ] - NODE 20: Post-processing 00000017>>FFFFFFFF
  80495:2017-02-06 21:20:53.293 [DEBUG] [.b.z.handler.ZWaveThingHandler:1491 ] - NODE 20: Sub-parameter setting config_2_1 is 00000017 [23]
  80496:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing nodename_name
  80497:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing wakeup_node
  80498:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing nodename_location
  80499:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_3_1
  80500:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_3_1 len=3
  80501:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_3_1 - id = '3'
  80502:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_4_1
  80503:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_4_1 len=3
  80504:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_4_1 - id = '4'
  80505:2017-02-06 21:20:53.294 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_5_1
  80506:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_5_1 len=3
  80507:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_5_1 - id = '5'
  80508:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing group_org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup@71420459
  80509:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1430 ] - NODE 20: Processing config_6_1
  80510:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1436 ] - NODE 20: Processing config_6_1 len=3
  80511:2017-02-06 21:20:53.295 [DEBUG] [.b.z.handler.ZWaveThingHandler:1443 ] - NODE 20: Processing config_6_1 - id = '6'
  80516:2017-02-06 21:20:53.296 [DEBUG] [.b.z.handler.ZWaveThingHandler:942  ] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
  80524:2017-02-06 21:20:54.194 [DEBUG] [ApplicationCommandMessageClass:42   ] - NODE 20: Application Command Request (ALIVE:DONE)
  80525:2017-02-06 21:20:54.194 [DEBUG] [p.i.ZWaveNodeInitStageAdvancer:190  ] - NODE 20: Starting initialisation from DONE
  80527:2017-02-06 21:20:54.194 [DEBUG] [ApplicationCommandMessageClass:152  ] - NODE 20: Incoming command class WAKE_UP
  80528:2017-02-06 21:20:54.194 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 20: Received Wake Up Request
  80529:2017-02-06 21:20:54.194 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:189  ] - NODE 20: Received WAKE_UP_NOTIFICATION
  80530:2017-02-06 21:20:54.194 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:441  ] - NODE 20: Is awake with 0 messages in the wake-up queue.
  80532:2017-02-06 21:20:54.194 [DEBUG] [.b.z.handler.ZWaveThingHandler:942  ] - NODE 20: Got an event from Z-Wave network: ZWaveWakeUpEvent
  80536:2017-02-06 21:20:55.195 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:546  ] - NODE 20: No more messages, go back to sleep
  80537:2017-02-06 21:20:55.195 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:207  ] - NODE 20: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
  80541:2017-02-06 21:20:55.196 [DEBUG] [b.z.handler.ZWaveSerialHandler:341  ] - NODE 20: Sending REQUEST Message = 01 09 00 13 14 02 84 08 25 1C 46 
  80551:2017-02-06 21:20:55.201 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 20: Sent Data successfully placed on stack.
80559:2017-02-06 21:20:55.217 [DEBUG] [b.z.i.p.s.SendDataMessageClass:76   ] - NODE 20: SendData Request. CallBack ID = 28, Status = Transmission complete and ACK received(0)

chris · February 7, 2017, 4:39pm

I’ll add it back in at the next update.

Avner · February 7, 2017, 5:38pm

Assuming the file is back in the database, what could be the reason that new configuration values don’t persist?
And why are the channels useless? They show up NaN (see img1 in my previous post)
Note that the protocol version in the database file is different then the one on my device.

chris · February 7, 2017, 5:42pm

I don’t know - I’d need to see a debug log.

Why do you think they are useless? Just because they show NaN this just means they aren’t initialised doesn’t it?

That doesn’t matter.

Avner · February 8, 2017, 6:36am

I restarted openhab2, initialised the device (node 20), and changed the On Time parameter in Configuration Parameters from 24 to 27 (I think this is logged as: NODE 20: Update CONFIGURATION 2/1 to 27)
The debug log is here
The new value does NOT persist after I restart openhab2 - it shows the original value. Also, the xml file always show the original value.
Also, in order to persist the new value, just before pressing Save (in Habmin, Configuration, Things), I press the button on the device to wake it up. I’m not sure if this is the right thing to do since the log file shows NODE 20: Starting initialisation from DONE. I hope I’m not starting the initialisation again.

The items/channels always show NaN, even if I refresh the PaperUI Control page after a while.
Is there a way to check that the channel values are transmitted? (maybe through the log file?)
I’m saying useless, because ultimately the goal is to get readings (e.g. temprature) from the device.
Is there a way to trigger an update of these channels / items from the device?

Also, do I need to define / create channels, items, or sitemap in order for these items to work properly? I’m asking because right now I’m only initialising the device - I have not edited any files such as .items or .sitemap (for reference, I do have another outlet device, and it works properly, i.e. turns the switch off / on from the PaperUI control, without any special configuration)
(I do see the items defined in ~/openhab2-master/git/openhab-distro/launch/home/userdata/jsondb/org.eclipse.smarthome.core.thing.Thing.json but I did not specifically create or manipulate this file in any way)

I do notice that I don’t have a temperature channel in the xml file that is being created during the initialisation.
In fact, all the 3 endpoints have the same information (they repeat the command classes of the device)
For example, for some reason command class is added to endpoint1, although only TEMERATURE should be added. I see the following log message

Endpoint 1: Adding command class MULTI_INSTANCE.

It looks to me that the commandClass that is created in ZWaveMultiInstanceCommandClass.java:413 is wrong (e.g. MULTI_INSTANCE instead of TEMPERATURE)

Another user who has an HSM100 device that works ok (although with a newer firmware) shared his xml file for comparison - his xml file does have a temperature channel.
@chris can you take a look at the xml file that is being generated (here) and see if it makes sense at all?
(for comparison, here is the other xml file that works ok for another user)
Thanks

Avner · February 11, 2017, 12:18am

@chris, after some more digging, I think that the “Multi-channel capability Report” payload is incorrect, or that the processing of it is wrong.
The result of the processing is 9 command classes (MULTI_INSTANCE, SENSOR_MULTILEVEL, CONFIGURATION, WAKE_UP, ASSOCIATION, BATTERY, MANUFACTURER_SPECIFIC, NODE_NAMING, VERSION) that are being added to each of the 3 endpoints in the node xml file (also see log file snippet1 below).
In the xml file, within the SENSOR_MULTILEVEL, the multiLevelSensorCommandClass

does not have any sensors/multilevelSensorType information
does have a “endpoint reference” field that points 4 levels up, i.e to the endpoints entry

But what it should be is:
endpoint1 - (SENSOR_MULTILEVEL with multiLevelSensorCommandClass/sensors/multilevelSensorType GENERAL, BASIC)
endpoint2 - (SENSOR_MULTILEVEL with multiLevelSensorCommandClass/sensors/multilevelSensorType LUMINANCE, BASIC)
endpoint3 - (SENSOR_MULTILEVEL with multiLevelSensorCommandClass/sensors/multilevelSensorType TEMPERATURE, BASIC)
as in the reference xml file (that another user shared) (should be downloaded for viewing since it fails to parse by the web browser)

snippet1

cat ~/avner/Dropbox/Public/zwave.log
...
2016-11-02 23:16:13.242 [DEBUG] [ZWaveMultiInstanceCommandClass:307 ]- NODE 32: Process Multi-channel capability Report
2016-11-02 23:16:13.242 [DEBUG] [ZWaveMultiInstanceCommandClass:313 ]- NODE 32: Endpoints are the same device class = true
2016-11-02 23:16:13.242 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 32: Endpoint Id = 1
2016-11-02 23:16:13.242 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 32: Endpoints is dynamic = false
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 32: Basic = Routing Slave 0x04
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 32: Generic = Multi-Level Sensor 0x21
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 32: Specific = Routing Multilevel Sensor 0x01
2016-11-02 23:16:13.243 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MULTI_INSTANCE
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class MULTI_INSTANCE.
2016-11-02 23:16:13.243 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class SENSOR_MULTILEVEL
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class SENSOR_MULTILEVEL.
2016-11-02 23:16:13.243 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class CONFIGURATION
2016-11-02 23:16:13.243 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class CONFIGURATION.
2016-11-02 23:16:13.244 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class WAKE_UP
2016-11-02 23:16:13.244 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class WAKE_UP.
2016-11-02 23:16:13.244 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class ASSOCIATION
2016-11-02 23:16:13.244 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class ASSOCIATION.
2016-11-02 23:16:13.244 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class BATTERY
2016-11-02 23:16:13.244 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class BATTERY.
2016-11-02 23:16:13.244 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-11-02 23:16:13.244 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class MANUFACTURER_SPECIFIC.
2016-11-02 23:16:13.245 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class NODE_NAMING
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class NODE_NAMING.
2016-11-02 23:16:13.245 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class VERSION
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 1: Adding command class VERSION.
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 32: Endpoint Id = 2
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 32: Endpoints is dynamic = false
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 32: Basic = Routing Slave 0x04
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 32: Generic = Multi-Level Sensor 0x21
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 32: Specific = Routing Multilevel Sensor 0x01
2016-11-02 23:16:13.245 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MULTI_INSTANCE
2016-11-02 23:16:13.245 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class MULTI_INSTANCE.
2016-11-02 23:16:13.246 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class SENSOR_MULTILEVEL
2016-11-02 23:16:13.246 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class SENSOR_MULTILEVEL.
2016-11-02 23:16:13.246 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class CONFIGURATION
2016-11-02 23:16:13.246 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class CONFIGURATION.
2016-11-02 23:16:13.246 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class WAKE_UP
2016-11-02 23:16:13.246 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class WAKE_UP.
2016-11-02 23:16:13.246 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class ASSOCIATION
2016-11-02 23:16:13.247 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class ASSOCIATION.
2016-11-02 23:16:13.247 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class BATTERY
2016-11-02 23:16:13.247 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class BATTERY.
2016-11-02 23:16:13.247 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class MANUFACTURER_SPECIFIC.
2016-11-02 23:16:13.248 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class NODE_NAMING
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class NODE_NAMING.
2016-11-02 23:16:13.248 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class VERSION
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 2: Adding command class VERSION.
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 32: Endpoint Id = 3
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 32: Endpoints is dynamic = false
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 32: Basic = Routing Slave 0x04
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 32: Generic = Multi-Level Sensor 0x21
2016-11-02 23:16:13.248 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 32: Specific = Routing Multilevel Sensor 0x01
2016-11-02 23:16:13.248 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MULTI_INSTANCE
2016-11-02 23:16:13.249 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class MULTI_INSTANCE.
2016-11-02 23:16:13.249 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class SENSOR_MULTILEVEL
2016-11-02 23:16:13.249 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class SENSOR_MULTILEVEL.
2016-11-02 23:16:13.249 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class CONFIGURATION
2016-11-02 23:16:13.249 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class CONFIGURATION.
2016-11-02 23:16:13.249 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class WAKE_UP
2016-11-02 23:16:13.249 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class WAKE_UP.
2016-11-02 23:16:13.249 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class ASSOCIATION
2016-11-02 23:16:13.249 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class ASSOCIATION.
2016-11-02 23:16:13.250 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class BATTERY
2016-11-02 23:16:13.250 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class BATTERY.
2016-11-02 23:16:13.250 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-11-02 23:16:13.250 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class MANUFACTURER_SPECIFIC.
2016-11-02 23:16:13.250 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class NODE_NAMING
2016-11-02 23:16:13.250 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class NODE_NAMING.
2016-11-02 23:16:13.250 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 32: Creating new instance of command class VERSION
2016-11-02 23:16:13.250 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 32: Endpoint 3: Adding command class VERSION.

Hamish · February 11, 2017, 12:56am

Just as an aside I appear to be having the same issues as avner.

I just installed openHAB on a RaspPi3 via openhabian and everything seems to be working apart from the HSM100’s.

The Z-Wave power switches are fine as you can see on the attached screenshot as they switch on and report the wattage consumption.

I am assuming the HSM’s are configured okay as a) they configured okay and operate okay when I installed homeassistant and b) they are accurately reporting the battery level. All the other fields (temp, luminance) either report -Nan/NULL or after a few screen updates a 0 value.

If you want me to pull out any logs etc for comparison purposes with avner let me know (otherwise I’ll keep a watch on this thread). If anything is required please err on the side of telling me how to suck eggs as I’m relatively unfamiliar with openhab (okay with Linux).

Thanks.

Avner · February 11, 2017, 7:34am

After more than 4 months, I got to say that I’m a bit frustrated with not being able to make use of the HSM100 device
I finally gave a try to Home Assistant. Within few minutes I was able to install the system!!
I couldn’t believe it when the HSM100 device popped up on the first zwave inclusion and immediately showed the temperature.
I’m going to give Home Assistant a try and keep monitoring this thread. I’m definitely not giving up on OpenHab,.
@chris, thanks for your help and efforts so far.

Hamish · February 11, 2017, 7:47am

Yes I had exactly the same result.

Openhab set up but wouldn’t give me any data other than battery from the HSM100. I loaded up homeassistant and it read the data first pop.

Great I thought! I can deal with the fairly mundane interface with limited configuration possibilities and yaml config files.

I then noticed that the HSM was only being updated when I reboot the PI. The rest of the time it just stored the data, so was virtually useless to run a virtual thermostat off.

Let me know how you get on and if yours update with each polling (I didn’t manage to examine whether they continued polling after the first boot as the base install zwave utilities on homeassistant aren’t anywhere near as comprehensive as habmin).

Avner · February 11, 2017, 7:52am

So far I’m getting results for luminance, temperature, and battery. I’m not sure if it is actually polling because the values are fixed, but I have only ran it only for 20 minutes. I’ll give it to run and let you know if the values actually change with each polling.

Hamish · February 11, 2017, 7:56am

Thanks.

I think I got actual values as the temperatures were fairly believable.

The give away was later in the night when the luminance was still high in a dark room

chris · February 11, 2017, 10:18am

Information on sensors etc is not included in the multi-channel command class - it’s included elsewhere in subsequent requests, so I would doubt that this is the problem.

I can only apologise for not getting this resolved. However, I’ve also put quite a lot of time into trying to help where I can, and it is very difficult to try and debug a device I don’t have remotely.

If there are a lot of people who have this, I could look to buy one to get it working - but until now it’s only one or two people and it’s hard for me to justify spending money on a device I won’t use myself with so few people seemingly having this device (I already have a lot of devices I’ve purchased to help others).

sihui · February 11, 2017, 12:09pm

From my point of view there is no need to apologize ever … your 99.9 % success in making the zwave binding work is far more than enough

Avner · February 11, 2017, 5:27pm

@chris, I feel exactly like shiui. You don’t need to apologise. Actually, the opposite. The reason I’m sticking with this issue is that I see responsiveness and solutions in so many other threads that encourage me to keep digging. (I understand the difficulty of not having the device, and understanding my questions since I may be mixing terms being an Openhab / zwave noob)

What would help me are directions in response to my questions that will send me digging more until I find a solution
Can you look at the xml file here and tell me:

is it expected to have all 9 command classes appear identicaly for each of the endpoints? (I mentioned the details in this post)
is it expected not to have Temperature, and Luminance entries? (compared to this reference from another user)
I want to make sure that node XML file is correct before investigating beyond initialisation
Thanks again.

Hamish · February 12, 2017, 1:16am

Hi Chris

I’m a relative new comer to this thread and wanted to echo the other comments that there is no need to apologise as it looks like you’ve put a significant amount of resource in (I know I wouldn’t be a popular person at home if I worked on an open source project while on holiday as you did

The HSM100 I’ve got is pretty old. I acquired them a number of years ago so they probably aren’t even available now.

I’d be happy to mail you one of mine if that helps (preference is to get it back if possible :-), as they aren’t doing anything given the issues I currently have with homassistant and openhab?

Regards

vespaman · February 12, 2017, 5:31pm

I never got my HSM100 (Express Control EZMotion 3in1) to work with OH either. But it may be a unrelated issue, it was so long time ago since I gave up, that I don’t remember anymore…

I decided to give it a go by pressing the button on the side for a NIF, I get;

17:45:12.769 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update request. Node information received.
17:45:12.770 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Node is ALIVE. Init stage is PING.
17:45:12.770 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
17:45:12.770 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node Status event during initialisation - Node is ALIVE
17:45:12.770 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - PING: queue length(0), free to send(true)
17:45:12.770 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - PING try 1: stageAdvanced(false)
17:45:12.770 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: PING - send NoOperation
17:45:12.770 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 53: Creating new message for command No Operation
17:45:12.770 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - queued packet. Queue length is 1
17:45:12.770 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
17:45:12.770 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
17:45:12.770 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 53: Node Status event - Node is ALIVE
17:45:12.770 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 35 01 00 25 87 72 
17:45:12.770 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class MULTI_INSTANCE
17:45:12.770 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 53: Sending REQUEST Message = 01 08 00 13 35 01 00 25 87 72 
17:45:12.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class MULTI_INSTANCE, endpoint null created
17:45:12.771 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class MULTI_INSTANCE.
17:45:12.771 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class MULTI_INSTANCE to the list of supported command classes.
17:45:12.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class CONFIGURATION
17:45:12.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class CONFIGURATION, endpoint null created
17:45:12.771 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class CONFIGURATION.
17:45:12.771 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class CONFIGURATION to the list of supported command classes.
17:45:12.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class WAKE_UP
17:45:12.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class WAKE_UP, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class WAKE_UP.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class WAKE_UP to the list of supported command classes.
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class ASSOCIATION
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class ASSOCIATION, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class ASSOCIATION.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class ASSOCIATION to the list of supported command classes.
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class BATTERY
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class BATTERY, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class BATTERY.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class BATTERY to the list of supported command classes.
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class MANUFACTURER_SPECIFIC
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class MANUFACTURER_SPECIFIC, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class MANUFACTURER_SPECIFIC.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes.
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class NODE_NAMING
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class NODE_NAMING, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class NODE_NAMING.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class NODE_NAMING to the list of supported command classes.
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class VERSION
17:45:12.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class VERSION, endpoint null created
17:45:12.772 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update is adding command class VERSION.
17:45:12.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 53: Adding command class VERSION to the list of supported command classes.
17:45:12.773 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Is awake with 0 messages in the wake-up queue.
17:45:12.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
17:45:12.773 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Wakeup during initialisation.
17:45:12.773 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - PING: queue length(1), free to send(false)
17:45:12.773 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - queued packet. Queue length is 1
17:45:12.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
17:45:12.773 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=38, callback=134, payload=26 07 60 0D 01 01 25 01 FF 
17:45:12.773 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 35 0E 04 21 01 60 31 70 84 85 80 72 77 86 EF 20 
17:45:12.773 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=134, expected=SendData, cancelled=false      MISMATCH
17:45:13.773 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: No more messages, go back to sleep
17:45:13.773 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION

Then I get a notification about a new thing, which I add. But it does not arrive into the ‘thing list’ under configuration.
I push the nif button again, and get;

18:21:14.989 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 53: Application update request. Node information received.
18:21:14.989 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Is awake with 2 messages in the wake-up queue.
18:21:14.989 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
18:21:14.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Wakeup during initialisation.
18:21:14.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - PING: queue length(1), free to send(false)
18:21:14.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - queued packet. Queue length is 1
18:21:14.989 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
18:21:14.989 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
18:21:14.989 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
18:21:14.989 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 35 01 00 25 ED 18 
18:21:14.989 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=20, callback=235, payload=14 02 26 02 
18:21:14.989 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 53: Sending REQUEST Message = 01 08 00 13 35 01 00 25 ED 18 
18:21:14.989 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 35 0E 04 21 01 60 31 70 84 85 80 72 77 86 EF 20 
18:21:14.990 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=235, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
18:21:14.996 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
18:21:14.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:14.997 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
18:21:14.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
18:21:14.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
18:21:14.997 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: Sent Data successfully placed on stack.
18:21:15.013 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 ED 00 00 02 04 
18:21:15.013 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.013 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 ED 00 00 02 00 00 0A 
18:21:15.013 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 ED 00 00 02 00 00 0A 
18:21:15.013 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=ED 00 00 02 
18:21:15.013 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: SendData Request. CallBack ID = 237, Status = Transmission complete and ACK received(0)
18:21:15.014 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=53, callback=237, payload=35 01 00 
18:21:15.014 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=ED 00 00 02 
18:21:15.014 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=237, expected=SendData, cancelled=false        transaction complete!
18:21:15.014 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - PING: Transaction complete (SendData:Request) success(true)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - checking initialisation queue. Queue size 1.
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - message removed from queue. Queue size 0.
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - PING: queue length(0), free to send(true)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - PING try 2: stageAdvanced(false)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - advancing to DETAILS
18:21:15.014 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: received RequestNodeInfo
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - advancing to INCLUSION_START
18:21:15.014 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - INCLUSION_START try 0: stageAdvanced(true)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: Unknown node state INCLUSION_START encountered.
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - advancing to IDENTIFY_NODE
18:21:15.014 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - IDENTIFY_NODE try 0: stageAdvanced(true)
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: PROTOINFO - send IdentifyNode
18:21:15.014 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - queued packet. Queue length is 1
18:21:15.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
18:21:15.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
18:21:15.015 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 53: Response processed after 25ms/4984ms.
18:21:15.015 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
18:21:15.015 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 35 01 00 25 EF 1A 
18:21:15.015 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 53: Sending REQUEST Message = 01 08 00 13 35 01 00 25 EF 1A 
18:21:15.022 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
18:21:15.022 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.022 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
18:21:15.022 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
18:21:15.022 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
18:21:15.022 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: Sent Data successfully placed on stack.
18:21:15.038 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EF 00 00 02 06 
18:21:15.038 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.039 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 EF 00 00 02 00 00 08 
18:21:15.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 EF 00 00 02 00 00 08 
18:21:15.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=EF 00 00 02 
18:21:15.039 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: SendData Request. CallBack ID = 239, Status = Transmission complete and ACK received(0)
18:21:15.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=53, callback=239, payload=35 01 00 
18:21:15.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=EF 00 00 02 
18:21:15.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=239, expected=SendData, cancelled=false        transaction complete!
18:21:15.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:21:15.039 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - IDENTIFY_NODE: Transaction complete (SendData:Request) success(true)
18:21:15.039 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - checking initialisation queue. Queue size 1.
18:21:15.039 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 53: Response processed after 24ms/4984ms.
18:21:15.039 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
18:21:15.039 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 35 02 84 08 25 EE 95 
18:21:15.039 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 53: Sending REQUEST Message = 01 09 00 13 35 02 84 08 25 EE 95 
18:21:15.046 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
18:21:15.046 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.046 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
18:21:15.046 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
18:21:15.046 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
18:21:15.047 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: Sent Data successfully placed on stack.
18:21:15.063 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EE 00 00 02 07 
18:21:15.063 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.064 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 EE 00 00 02 00 00 09 
18:21:15.064 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 EE 00 00 02 00 00 09 
18:21:15.064 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=EE 00 00 02 
18:21:15.064 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 53: SendData Request. CallBack ID = 238, Status = Transmission complete and ACK received(0)
18:21:15.064 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=53, callback=238, payload=35 02 84 08 
18:21:15.064 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=EE 00 00 02 
18:21:15.064 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=238, expected=SendData, cancelled=false        transaction complete!
18:21:15.064 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:21:15.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - IDENTIFY_NODE: Transaction complete (SendData:Request) success(true)
18:21:15.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - checking initialisation queue. Queue size 1.
18:21:15.064 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Went to sleep
18:21:15.064 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Is sleeping
18:21:15.064 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 53: Response processed after 25ms/4984ms.
18:21:15.064 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
18:21:15.065 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 35 8F 
18:21:15.065 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 35 8F 
18:21:15.066 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 51 8C 00 04 21 01 4F 
18:21:15.067 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
18:21:15.067 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 51 8C 00 04 21 01 4F 
18:21:15.067 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 51 8C 00 04 21 01 4F 
18:21:15.067 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=51 8C 00 04 21 01 
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: ProtocolInfo
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Listening = false
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Routing = true
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Beaming = false
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Version = 2
18:21:15.067 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: FLIRS = false
18:21:15.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Security = false
18:21:15.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Max Baud = 40000
18:21:15.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Basic = Routing Slave
18:21:15.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Generic = Multi-Level Sensor
18:21:15.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 53: Specific = Routing Multilevel Sensor
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class NO_OPERATION
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class NO_OPERATION, endpoint null created
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Version = 1, version set. Enabling extra functionality.
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class BASIC
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class BASIC, endpoint null created
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Creating new instance of command class SENSOR_MULTILEVEL
18:21:15.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 53: Command class SENSOR_MULTILEVEL, endpoint null created
18:21:15.068 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=35 
18:21:15.068 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=51 8C 00 04 21 01 
18:21:15.068 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
18:21:15.068 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:21:15.068 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - IDENTIFY_NODE: Transaction complete (IdentifyNode:Request) success(true)
18:21:15.068 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - checking initialisation queue. Queue size 1.
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - message removed from queue. Queue size 0.
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - IDENTIFY_NODE: queue length(0), free to send(true)
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - IDENTIFY_NODE try 1: stageAdvanced(false)
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - advancing to MANUFACTURER
18:21:15.069 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer: MANUFACTURER - send ManufacturerSpecific
18:21:15.069 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 53: Creating new message for command MANUFACTURER_SPECIFIC_GET
18:21:15.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 53: Node advancer - queued packet. Queue length is 1
18:21:15.069 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Putting message SendData in wakeup queue.
18:21:15.069 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 53: Putting message SendData in wakeup queue.

Does this look like the same issue?
I haven’t done any reset or removal of the device, it has been located by the stick since before summer, when I gave up on it.

Avner · February 14, 2017, 8:42am

More observations…
I initialised the device in several attempts, and got different results depending on the timing on which I pressed the button to wake up the device.
At one attempt I got no sensors created, at a second I got 1 sensor created and 2 not created, and at a third attempt I got all 3 created with UNKNOWN.
I think that the initialisation is progressing beyond the ENDPOINTS stage, without waiting to the received response for each of the endpoints.
(I think that this is done in ZWaveMultiInstanceCommandClass.java in handleMultiChannelCapabilityReportResponse)

chris · February 14, 2017, 8:47am

Please provide some logs showing what’s happening. It’s probably not impossible for this to happen, but the OH2 binding tries pretty hard to get the information it needs but it will also timeout after a while if it doesn’t get the responses.

Note that “sensors” are not created during the ENDPOINTS stage - this is done during the STATIC stage.

Avner · February 15, 2017, 4:48am

Thanks for clarifying where sensors are reated.
The log files for

case 1 (1 sensor created and 2 not created) is here
case 2 (no sensors created) is here

Avner · February 15, 2017, 4:53am

Just an update that the readings in Home Assistant do change, but very slightly and the temperature value seems inaccurate (I’m getting 27 Celsius at home, while it is more like 21), so I’m still hoping that this can be resolved within openhab.