Z-Wave Problems with OH2+Habmin2+Zwave2

Setup, Configuration and Use Runtime
,
1

Hi there,

I’m a total Zwave noob; just got a ZME Serial Stick, a Aeon Smart Switch 6 (powered) and a ZG8101 Garage Door Tilt Sensor (battery). I’m running OH2 on a Raspberry Pi 2 with Raspbian. Other bindings work very well (e.g. KNX 1.9, http).

I got everythin set up following @chris instructions.

Group item=GarageDoor label="Garagentor" icon="rollershutter"{
	Text item=zwave_device_153d3725a86_node6_battery_level 			
	Text item=zwave_device_153d3725a86_node6_sensor_binary
	Text item=zwave_device_153d3725a86_node6_alarm_burglar		
}
Text label="Switch" icon="switch"{
	Text item=zwave_device_153d3725a86_node5_meter_watts
	Text item=zwave_device_153d3725a86_node5_meter_kwh
	Text item=zwave_device_153d3725a86_node5_meter_current
	Text item=zwave_device_153d3725a86_node5_meter_voltage
	Switch item=zwave_device_153d3725a86_node5_meter_reset
	Switch item=zwave_device_153d3725a86_node5_switch_binary
}

All channels are linked to the devices that habmin2 has created automatically. I referenced them in the sitemap as stated above. I configured the minimal polling period to 30.

I have the following issues:

  • The Switch actuator works fine, I can trigger it through OH2
  • Most sensors never update automatically, neither in the UI nor any update messages in the OH log
  • The battery powered tilt sensor never shows any value at all
  • The switch shows its energy sensor values like volts, amps, kwH, W exactly once but will not update
  • I let the setup run for several days in order to see if there are some wakeup times required for sensor updated, but no change, even after about a week, no values…

Did I miss smth fundamental that enables the sensors to regularly send their measurements?

2

Here is a debug log from the polling of the switch. My first impression is that the different channels get polled, but all the meter polls return in scale kwh and thus, the same value. So it returns only the kwh and not the voltage, current or watts. How could that be?

Next to these debug messages, I don’t see any ThingUpdatedEvent that actually changes the OH-value, while at least the kwh-meter should update its channel, shouldn’t it?

01:40:12.458 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
01:40:12.458 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:meter_kwh
01:40:12.459 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.459 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.460 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
01:40:12.460 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:meter_current
01:40:12.461 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.462 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.462 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
01:40:12.463 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:meter_voltage
01:40:12.463 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.463 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.464 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
01:40:12.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:meter_watts
01:40:12.464 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.465 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.465 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
01:40:12.465 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:meter_reset
01:40:12.466 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.466 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for METER, endpoint 0
01:40:12.466 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
01:40:12.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:153d3725a86:node5:switch_binary
01:40:12.467 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 5: Generating poll message for SWITCH_BINARY, endpoint 0
01:40:12.468 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_GET
01:40:12.468 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
01:40:12.469 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
01:40:12.469 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
01:40:12.469 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
01:40:12.470 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
01:40:12.470 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
01:40:12.470 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 32 01 25 E3 17
01:40:12.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
01:40:12.471 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 32 01 25 E3 17
01:40:12.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.481 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.482 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.483 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.484 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.484 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.498 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E3 00 00 02 0A
01:40:12.500 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.502 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E3 00 00 02 00 00 04
01:40:12.506 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E3 00 00 02 00 00 04
01:40:12.510 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 1D 00 00 01 42 00 00 00 00 9C
01:40:12.511 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E3 00 00 02
01:40:12.512 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 227, Status = Transmission complete and ACK received(0)
01:40:12.513 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.514 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E3 00 00 02
01:40:12.515 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=227, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.515 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.517 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 1D 00 00 01 42 00 00 00 00 9C
01:40:12.520 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 1D 00 00 01 42 00 00 00 00 9C
01:40:12.522 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 1D 00 00 01 42 00 00 00 00
01:40:12.524 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.527 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class METER
01:40:12.528 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Received Meter Request
01:40:12.529 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=0.322, Delta=29
01:40:12.531 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
01:40:12.532 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.534 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 1D 00 00 01 42 00 00 00 00
01:40:12.534 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=227, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.535 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.537 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 65ms/4196ms.
01:40:12.538 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
01:40:12.542 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 32 01 25 E4 10
01:40:12.544 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 32 01 25 E4 10
01:40:12.556 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.558 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.559 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.559 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.560 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.561 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.570 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E4 00 00 02 0D
01:40:12.572 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.576 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E4 00 00 02 00 00 03
01:40:12.579 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E4 00 00 02 00 00 03
01:40:12.582 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E4 00 00 02
01:40:12.584 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 228, Status = Transmission complete and ACK received(0)
01:40:12.585 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.586 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E4 00 00 02
01:40:12.587 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.587 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=228, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.593 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.596 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.599 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.601 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.602 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class METER
01:40:12.604 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Received Meter Request
01:40:12.605 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=0.322, Delta=0
01:40:12.606 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
01:40:12.607 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.608 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.609 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=228, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.609 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.609 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 64ms/4196ms.
01:40:12.610 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
01:40:12.611 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 32 01 25 E5 11
01:40:12.612 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 32 01 25 E5 11
01:40:12.621 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.624 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.625 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.626 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.627 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.636 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E5 00 00 03 0D
01:40:12.640 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.641 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E5 00 00 03 00 00 03
01:40:12.642 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E5 00 00 03 00 00 03
01:40:12.642 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E5 00 00 03
01:40:12.643 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 229, Status = Transmission complete and ACK received(0)
01:40:12.644 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.645 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E5 00 00 03
01:40:12.646 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=229, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.652 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 01 00 00 01 42 00 00 00 00 80
01:40:12.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.658 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 01 00 00 01 42 00 00 00 00 80
01:40:12.660 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 01 00 00 01 42 00 00 00 00 80
01:40:12.662 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 01 00 00 01 42 00 00 00 00
01:40:12.663 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.664 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class METER
01:40:12.665 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Received Meter Request
01:40:12.666 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=0.322, Delta=1
01:40:12.667 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
01:40:12.669 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.670 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 01 00 00 01 42 00 00 00 00
01:40:12.671 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=229, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.671 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.672 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 59ms/4196ms.
01:40:12.672 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
01:40:12.673 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 32 01 25 E6 12
01:40:12.673 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 32 01 25 E6 12
01:40:12.684 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.685 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.686 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.687 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.689 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.698 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E6 00 00 02 0F
01:40:12.701 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.703 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E6 00 00 02 00 00 01
01:40:12.706 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E6 00 00 02 00 00 01
01:40:12.708 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E6 00 00 02
01:40:12.710 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 230, Status = Transmission complete and ACK received(0)
01:40:12.713 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.715 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E6 00 00 02
01:40:12.716 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.718 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=230, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.723 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.725 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.728 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.730 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.731 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.732 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class METER
01:40:12.733 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Received Meter Request
01:40:12.734 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=0.322, Delta=0
01:40:12.735 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
01:40:12.736 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.738 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.739 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=230, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.739 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.742 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 67ms/4196ms.
01:40:12.743 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
01:40:12.744 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 32 01 25 E7 13
01:40:12.745 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 32 01 25 E7 13
01:40:12.755 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.757 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.758 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.759 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.760 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.761 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.771 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E7 00 00 02 0E
01:40:12.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.776 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E7 00 00 02 00 00 00
01:40:12.778 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E7 00 00 02 00 00 00
01:40:12.780 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E7 00 00 02
01:40:12.781 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)
01:40:12.783 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.784 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E7 00 00 02
01:40:12.785 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=231, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.786 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.789 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.791 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.794 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00 81
01:40:12.795 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.796 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.797 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class METER
01:40:12.798 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Received Meter Request
01:40:12.799 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=0.322, Delta=0
01:40:12.800 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
01:40:12.801 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 32 01
01:40:12.804 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 12 32 02 21 64 00 00 01 42 00 00 00 00 01 42 00 00 00 00
01:40:12.806 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=231, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.807 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.809 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 63ms/4196ms.
01:40:12.810 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
01:40:12.811 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 25 02 25 E8 08
01:40:12.813 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 25 02 25 E8 08
01:40:12.823 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:40:12.824 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.825 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:40:12.826 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:40:12.826 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01
01:40:12.827 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
01:40:12.838 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E8 00 00 02 01
01:40:12.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.842 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E8 00 00 02 00 00 0F
01:40:12.843 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E8 00 00 02 00 00 0F
01:40:12.845 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E8 00 00 02
01:40:12.846 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 232, Status = Transmission complete and ACK received(0)
01:40:12.848 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 25 02
01:40:12.850 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=E8 00 00 02
01:40:12.850 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 FF 2D
01:40:12.852 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=232, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:40:12.853 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:40:12.855 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 FF 2D
01:40:12.858 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 FF 2D
01:40:12.859 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 03 25 03 FF
01:40:12.859 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
01:40:12.860 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
01:40:12.860 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
01:40:12.861 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 255
01:40:12.861 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
01:40:12.863 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, payload=05 02 25 02
01:40:12.865 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 05 03 25 03 FF
01:40:12.865 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=232, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:40:12.866 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:40:12.867 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 53ms/4196ms.
3

There are three things that come to mind here. First, check configuration parameter 80. Set it to Basic CC report.

The next other thing to check is to make sure the association is set to the controller. This has a caveat in that it might work to set it in tonight’s build. Setting associations has been broken pending an update to ESH. It looks like, if I am reading it correctly, the build that just happened would be the first one that might have this fixed. I have not tried it yet though.

The third thing is there seems to be a problem at start-up time where some configurations are read out of order. @chris probably has a better grasp on this, but the result is that some devices work some times. A restart of OH2 may, at least in my case, make it work until the next restart.

I am looking forward to trying the new build.

4

Thanks for the report @SuperOok.

There is a bug in the polling code for the meter that was introduced after a recent change in the database, so you are right, we are currently polling all the same channel. However, most of these devices should be configurable to send the data without polling which is preferable (and probably why this hasn’t been spotted yet :wink:).

Yes - something is missing here. I don’t see any event processing messages which likely means the event handler isn’t installed for this node - I’m not sure why this is at the moment, but there are some issues with the initialisation of bindings and the event notifications between the stick and it’s children so it might be related to this.

I would guess that this is an association issue as Jim said. Currently we’re waiting on an updated ESH to flow through before this works again.

It will likely still be another couple of days before there’s an update as I want to get the new ESH and some other changes merged upstream first.

5

Last night’s build seems to have the upstream ESH update @chris mentioned for associations in it. I verified it was merged and ESH was updated for OH2, then redeployed after the build last night, and associations are saving again for me. The other changes are not quite there yet though.

6

Ok, no problem, I can wait. Thanks for the confirmation that it’s not just me :wink: