AEON Labs Smart Dimmer 6

Julian_Kranz · January 5, 2017, 9:41pm

Hello,

the AEON Labs Smart Dimmer 6 (ZW099) seems to miss some endpoints; only the dimmer functionality works, power consumption always shows a zero value and voltage is missing altogether. I wanted to upload the node*.xml, but no matter what I do (include, exclude, remove from database in the jar file…), OH2 does not generate a node*.xml file. Does anyone have an idea?

Greetings,
Julian

chris · January 5, 2017, 10:10pm

I’m not sure if it’s missing endpoints or not - it might be missing a channel or two…

Anyway, if the XML is missing, then I would suggest to get a log and find out why it’s not completing.

Julian_Kranz · January 5, 2017, 11:00pm

Here is the whole openhab.log since it’s startup:

2017-01-05 22:43:28.619 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node76_sensor_temperature-zwave:device:86d1d009:node76:sensor_temperature' has been added.
2017-01-05 22:43:28.679 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node18_alarm_flood-zwave:device:86d1d009:node18:alarm_flood' has been added.
2017-01-05 22:43:28.710 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node18_alarm_burglar-zwave:device:86d1d009:node18:alarm_burglar' has been added.
2017-01-05 22:43:28.715 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node18_battery_level-zwave:device:86d1d009:node18:battery-level' has been added.
2017-01-05 22:43:28.719 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node18_sensor_binary-zwave:device:86d1d009:node18:sensor_binary' has been added.
2017-01-05 22:43:29.204 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node18_sensor_binary' has been added.
2017-01-05 22:43:29.216 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node18_alarm_flood' has been added.
2017-01-05 22:43:29.226 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node18_alarm_burglar' has been added.
2017-01-05 22:43:29.234 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node18_battery_level' has been added.
2017-01-05 22:43:29.289 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node18' has been added.
2017-01-05 22:43:29.304 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:43:29.317 [ThingAddedEvent           ] - Thing 'zwave:serial_zstick:86d1d009' has been added.
2017-01-05 22:43:29.590 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:86d1d009' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:43:29.597 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node77' has been added.
2017-01-05 22:43:29.612 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:86d1d009' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:43:29.636 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:43:29.641 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node76_sensor_temperature' has been added.
2017-01-05 22:43:30.091 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node76' has been added.
2017-01-05 22:43:30.132 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:43:30.137 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2017-01-05 22:43:30.161 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2017-01-05 22:43:30.175 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:43:30.194 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:43:30.235 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:43:32.891 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:43:33.196 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node77_switch_dimmer' has been added.
2017-01-05 22:43:33.200 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node77_switch_dimmer-zwave:device:86d1d009:node77:switch_dimmer' has been added.
2017-01-05 22:43:33.228 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node77_meter_kwh' has been added.
2017-01-05 22:43:33.233 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node77_meter_kwh-zwave:device:86d1d009:node77:meter_kwh' has been added.
2017-01-05 22:43:33.253 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node77_meter_watts' has been added.
2017-01-05 22:43:33.257 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node77_meter_watts-zwave:device:86d1d009:node77:meter_watts' has been added.
2017-01-05 22:43:33.706 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2017-01-05 22:43:33.719 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:43:33.737 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node77' has been updated.
2017-01-05 22:43:40.053 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:86d1d009' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:43:40.069 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:43:40.078 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to OFFLINE: zwave.thingstate.node_notfound
2017-01-05 22:43:40.134 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:43:40.880 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node18' has been updated.
2017-01-05 22:43:40.992 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:43:55.046 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node18_sensor_binary changed from NULL to OFF
2017-01-05 22:43:55.113 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node18_alarm_flood changed from NULL to OFF
2017-01-05 22:43:55.160 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node18_battery_level changed from NULL to 100
2017-01-05 22:43:55.184 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node76_sensor_temperature changed from NULL to 0
2017-01-05 22:44:15.567 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE to ONLINE: Node initialising: INIT_NEIGHBORS
2017-01-05 22:44:15.831 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from ONLINE to ONLINE: Node initialising: PROTOINFO
2017-01-05 22:44:15.838 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from ONLINE: Node initialising: PROTOINFO to ONLINE: Node initialising: INIT_NEIGHBORS
2017-01-05 22:44:16.646 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-01-05 22:44:16.825 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-01-05 22:44:17.249 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: WAIT
2017-01-05 22:44:17.261 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: WAIT to ONLINE: Node initialising: PING
2017-01-05 22:44:17.529 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node18' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: WAIT
2017-01-05 22:44:17.582 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: PING to ONLINE
2017-01-05 22:44:22.650 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE to ONLINE: Node initialising: DETAILS
2017-01-05 22:44:22.799 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: DETAILS to ONLINE: Node initialising: INCLUSION_START
2017-01-05 22:44:22.806 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: INCLUSION_START to ONLINE: Node initialising: IDENTIFY_NODE
2017-01-05 22:44:22.854 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: IDENTIFY_NODE to ONLINE: Node initialising: MANUFACTURER
2017-01-05 22:44:22.934 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: MANUFACTURER to ONLINE: Node initialising: SECURITY_REPORT
2017-01-05 22:44:22.944 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: SECURITY_REPORT to ONLINE: Node initialising: APP_VERSION
2017-01-05 22:44:23.105 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: APP_VERSION to ONLINE: Node initialising: DISCOVERY_COMPLETE
2017-01-05 22:44:23.110 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: DISCOVERY_COMPLETE to ONLINE: Node initialising: VERSION
2017-01-05 22:44:24.304 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: VERSION to ONLINE: Node initialising: ENDPOINTS
2017-01-05 22:44:24.504 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: ENDPOINTS to ONLINE: Node initialising: UPDATE_DATABASE
2017-01-05 22:44:24.521 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: UPDATE_DATABASE to ONLINE: Node initialising: STATIC_VALUES
2017-01-05 22:44:38.735 [ExtensionEvent            ] - Extension 'action-telegram' has been installed.
2017-01-05 22:44:38.748 [ExtensionEvent            ] - Extension 'binding-exec' has been installed.
2017-01-05 22:44:38.752 [ExtensionEvent            ] - Extension 'action-pushsafer' has been installed.
2017-01-05 22:44:38.758 [ExtensionEvent            ] - Extension 'persistence-jdbc-mysql' has been installed.
2017-01-05 22:44:38.762 [ExtensionEvent            ] - Extension 'ui-basic' has been installed.
2017-01-05 22:44:38.775 [ExtensionEvent            ] - Extension 'ui-classic' has been installed.
2017-01-05 22:44:38.778 [ExtensionEvent            ] - Extension 'misc-openhabcloud' has been installed.
2017-01-05 22:44:38.784 [ExtensionEvent            ] - Extension 'ui-habmin' has been installed.
2017-01-05 22:44:38.788 [ExtensionEvent            ] - Extension 'misc-myopenhab' has been installed.
2017-01-05 22:44:38.794 [ExtensionEvent            ] - Extension 'ui-habpanel' has been installed.
2017-01-05 22:44:38.800 [ExtensionEvent            ] - Extension 'misc-ruleengine' has been installed.
2017-01-05 22:44:38.804 [ExtensionEvent            ] - Extension 'ui-paper' has been installed.
2017-01-05 22:44:54.624 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from OFFLINE: zwave.thingstate.node_notfound to REMOVING
2017-01-05 22:44:54.653 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from REMOVING to REMOVED
2017-01-05 22:44:54.695 [ItemRemovedEvent          ] - Item 'zwave_device_86d1d009_node76_sensor_temperature' has been removed.
2017-01-05 22:44:54.705 [temChannelLinkRemovedEvent] - Link 'zwave_device_86d1d009_node76_sensor_temperature => zwave:device:86d1d009:node76:sensor_temperature' has been removed.
2017-01-05 22:44:54.720 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node76' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:44:54.877 [ThingRemovedEvent         ] - Thing 'zwave:device:86d1d009:node76' has been removed.
2017-01-05 22:44:58.634 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from REMOVING to REMOVED
2017-01-05 22:44:58.636 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE: Node initialising: STATIC_VALUES to REMOVING
2017-01-05 22:44:58.652 [ItemRemovedEvent          ] - Item 'zwave_device_86d1d009_node77_switch_dimmer' has been removed.
2017-01-05 22:44:58.664 [temChannelLinkRemovedEvent] - Link 'zwave_device_86d1d009_node77_switch_dimmer => zwave:device:86d1d009:node77:switch_dimmer' has been removed.
2017-01-05 22:44:58.676 [ItemRemovedEvent          ] - Item 'zwave_device_86d1d009_node77_meter_kwh' has been removed.
2017-01-05 22:44:58.682 [temChannelLinkRemovedEvent] - Link 'zwave_device_86d1d009_node77_meter_kwh => zwave:device:86d1d009:node77:meter_kwh' has been removed.
2017-01-05 22:44:58.692 [ItemRemovedEvent          ] - Item 'zwave_device_86d1d009_node77_meter_watts' has been removed.
2017-01-05 22:44:58.696 [temChannelLinkRemovedEvent] - Link 'zwave_device_86d1d009_node77_meter_watts => zwave:device:86d1d009:node77:meter_watts' has been removed.
2017-01-05 22:44:58.706 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:44:58.784 [ThingRemovedEvent         ] - Thing 'zwave:device:86d1d009:node77' has been removed.
2017-01-05 22:45:07.465 [InboxAddedEvent           ] - Discovery Result with UID 'zwave:device:86d1d009:node77' has been added.
2017-01-05 22:45:07.507 [InboxAddedEvent           ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:45:10.352 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@1df9d33
2017-01-05 22:45:13.157 [InboxRemovedEvent         ] - Discovery Result with UID 'zwave:device:86d1d009:node77' has been removed.
2017-01-05 22:45:13.168 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node77' has been added.
2017-01-05 22:45:13.190 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:45:13.205 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:45:13.221 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:45:13.231 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:45:13.510 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2017-01-05 22:45:13.516 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node77' has been updated.
2017-01-05 22:45:13.541 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:45:13.548 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:45:13.581 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node77' has been updated.
2017-01-05 22:45:13.583 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:45:21.522 [InboxRemovedEvent         ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been removed.
2017-01-05 22:45:21.538 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:45:21.574 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:45:21.586 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:45:21.591 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:45:21.661 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:45:21.665 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:45:31.200 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node77_switch_dimmer' has been added.
2017-01-05 22:45:31.206 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node77_switch_dimmer-zwave:device:86d1d009:node77:switch_dimmer' has been added.
2017-01-05 22:45:38.029 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@1151227
2017-01-05 22:46:00.750 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from ONLINE to REMOVING
2017-01-05 22:46:00.768 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from REMOVING to REMOVED
2017-01-05 22:46:00.804 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:46:00.881 [ThingRemovedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been removed.
2017-01-05 22:46:10.972 [InboxAddedEvent           ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:46:12.804 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@fbb4de
2017-01-05 22:46:17.968 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@64535
2017-01-05 22:46:44.005 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@13bedb8
2017-01-05 22:47:00.057 [InboxRemovedEvent         ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been removed.
2017-01-05 22:47:00.070 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:47:00.110 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:47:00.127 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:47:00.139 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:47:00.177 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:47:00.196 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:47:50.874 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from ONLINE to REMOVING
2017-01-05 22:47:50.880 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from REMOVING to REMOVED
2017-01-05 22:47:50.939 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:47:51.054 [ThingRemovedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been removed.
2017-01-05 22:47:57.264 [InboxAddedEvent           ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:47:57.727 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@13a98c4
2017-01-05 22:48:09.694 [InboxRemovedEvent         ] - Discovery Result with UID 'zwave:device:86d1d009:node78' has been removed.
2017-01-05 22:48:09.708 [ThingAddedEvent           ] - Thing 'zwave:device:86d1d009:node78' has been added.
2017-01-05 22:48:09.744 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from UNINITIALIZED to INITIALIZING
2017-01-05 22:48:09.748 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:48:09.781 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:48:09.806 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:48:09.813 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:48:28.257 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:48:28.258 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:48:33.387 [BindingEvent              ] - org.openhab.binding.zwave.event.BindingEvent@1d95cb9
2017-01-05 22:48:51.685 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:48:51.688 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:48:52.838 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:48:52.842 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:48:52.875 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 22:48:53.104 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:48:53.118 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2017-01-05 22:48:53.125 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:48:53.127 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:48:55.750 [ItemAddedEvent            ] - Item 'zwave_device_86d1d009_node78_sensor_temperature' has been added.
2017-01-05 22:48:55.756 [ItemChannelLinkAddedEvent ] - Link 'zwave_device_86d1d009_node78_sensor_temperature-zwave:device:86d1d009:node78:sensor_temperature' has been added.
2017-01-05 22:49:03.154 [ItemCommandEvent          ] - Item 'zwave_device_86d1d009_node77_switch_dimmer' received command ON
2017-01-05 22:49:03.203 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node77_switch_dimmer changed from NULL to 100
2017-01-05 22:49:04.816 [ItemCommandEvent          ] - Item 'zwave_device_86d1d009_node77_switch_dimmer' received command OFF
2017-01-05 22:49:04.850 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node77_switch_dimmer changed from 100 to 0
2017-01-05 22:49:37.921 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:49:37.932 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node77' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:49:38.214 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node77' has been updated.
2017-01-05 22:49:59.414 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline
2017-01-05 22:49:59.423 [hingStatusInfoChangedEvent] - 'zwave:device:86d1d009:node78' changed from OFFLINE (BRIDGE_OFFLINE): zwave.thingstate.controller_offline to ONLINE
2017-01-05 22:49:59.460 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:49:59.473 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 22:49:59.485 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 22:50:20.751 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from NULL to 18.93
2017-01-05 22:54:14.374 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 18.93 to 0
2017-01-05 22:54:14.755 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 0 to 19.93
2017-01-05 22:58:08.709 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.93 to 19.37
2017-01-05 23:02:02.997 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.37 to 19.25
2017-01-05 23:05:57.244 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.25 to 19.18
2017-01-05 23:21:36.871 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.18 to 0
2017-01-05 23:21:37.567 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 0 to 19.18
2017-01-05 23:29:26.838 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.18 to 19.25
2017-01-05 23:37:15.064 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.25 to 19.31
2017-01-05 23:38:14.014 [ThingUpdatedEvent         ] - Thing 'zwave:device:86d1d009:node78' has been updated.
2017-01-05 23:38:14.041 [ConfigStatusInfoEvent     ] - ConfigStatusInfo [configStatusMessages=[]]
2017-01-05 23:45:03.439 [ItemStateChangedEvent     ] - zwave_device_86d1d009_node78_sensor_temperature changed from 19.31 to 19.37

Is there anywhere else to look? I don’t see a hint on why it isn’t creating the node*.xml file… It’s about node77.

chris · January 5, 2017, 11:08pm

The log doesn’t contain any debug - you probably need to go to the console an enable debug logging (log:set openhab.binding.zwave from memory).

Julian_Kranz · January 5, 2017, 11:25pm

I have now launched using start_debug.sh, but I don’t have the feeling I see much more messages:

2017-01-06 00:19:10.318 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jdbc.persist'
2017-01-06 00:19:10.683 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.persist'
2017-01-06 00:19:17.980 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'burglar.rules'
2017-01-06 00:19:18.474 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'flood.rules'
2017-01-06 00:19:26.646 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-01-06 00:19:29.982 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2017-01-06 00:19:30.299 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-06 00:19:34.665 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-06 00:19:35.800 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-01-06 00:19:38.674 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 3e416cf6-5a39-4ffd-a0f3-188f2f6627d7, base URL = http://localhost:8080)
2017-01-06 00:19:39.466 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: not authorized
2017-01-06 00:19:39.954 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-01-06 00:19:41.056 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2017-01-06 00:19:44.265 [INFO ] [egram.internal.TelegramActionService] - Bot jucs_openhab_bot loaded from config file
2017-01-06 00:19:53.643 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyS2'
2017-01-06 00:19:54.153 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-01-06 00:19:54.199 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-01-06 00:19:54.287 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-01-06 00:19:54.289 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-01-06 00:19:54.398 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.406 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.425 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.427 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.429 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.444 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-01-06 00:19:54.488 [ERROR] [apache.karaf.shell.support.ShellUtil] - Exception caught while executing command
java.lang.IllegalArgumentException: No enum constant org.apache.karaf.log.core.Level.OPENHAB.BINDING.ZWAVE
        at java.lang.Enum.valueOf(Enum.java:238)[:1.8.0_111]
        at org.apache.karaf.log.core.Level.valueOf(Level.java:23)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:125)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.command.SetLogLevel.execute(SetLogLevel.java:48)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[53:org.apache.karaf.shell.core:4.0.8]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2017-01-06 00:19:56.694 [ERROR] [apache.karaf.shell.support.ShellUtil] - Exception caught while executing command
java.lang.IllegalArgumentException: No enum constant org.apache.karaf.log.core.Level.OPENHAB.BINDING.ZWAVE
        at java.lang.Enum.valueOf(Enum.java:238)[:1.8.0_111]
        at org.apache.karaf.log.core.Level.valueOf(Level.java:23)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:125)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.command.SetLogLevel.execute(SetLogLevel.java:48)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[53:org.apache.karaf.shell.core:4.0.8]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2017-01-06 00:19:57.752 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-01-06 00:19:57.757 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-01-06 00:19:57.760 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2017-01-06 00:19:57.765 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2017-01-06 00:19:57.769 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2017-01-06 00:19:57.774 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2017-01-06 00:19:57.778 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2017-01-06 00:19:57.782 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2017-01-06 00:19:57.786 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2017-01-06 00:19:57.789 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2017-01-06 00:19:57.791 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2017-01-06 00:19:57.793 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 20: Node found
2017-01-06 00:19:57.794 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 21: Node found
2017-01-06 00:19:57.797 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 64: Node found
2017-01-06 00:19:57.799 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 77: Node found
2017-01-06 00:19:57.801 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 78: Node found
2017-01-06 00:19:57.805 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-01-06 00:19:57.807 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-01-06 00:19:57.809 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-01-06 00:19:57.812 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 16
2017-01-06 00:19:57.814 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-01-06 00:20:02.636 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 20: Is currently marked as failed by the controller!
2017-01-06 00:20:02.663 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 19: Is currently marked as failed by the controller!
2017-01-06 00:20:02.723 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 21: Is currently marked as failed by the controller!
2017-01-06 00:20:06.881 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 77: Initialising Thing Node...
2017-01-06 00:20:06.985 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 78: Initialising Thing Node...
2017-01-06 00:20:07.145 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Initialising Thing Node...
2017-01-06 00:20:07.771 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:20:07.774 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:09.303 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 77: Already processed another send data request for this callback Id, ignoring.
2017-01-06 00:20:14.301 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:20:14.303 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:14.602 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 19: Is currently marked as failed by the controller!
2017-01-06 00:20:14.647 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 21: Is currently marked as failed by the controller!
2017-01-06 00:20:14.707 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 20: Is currently marked as failed by the controller!
2017-01-06 00:20:21.286 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:20:21.288 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:26.312 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:20:26.315 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:31.331 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:20:31.333 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:36.353 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=77, callback=54, payload=4D 06 60 0D 01 01 33 01 
2017-01-06 00:20:41.374 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:20:41.377 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:44.842 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-01-06 00:20:44.944 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-01-06 00:20:45.008 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-01-06 00:20:45.156 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Shutting down my.openHAB service connection
2017-01-06 00:20:45.336 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Disconnected from my.openHAB service (UUID = 3e416cf6-5a39-4ffd-a0f3-188f2f6627d7, base URL = http://localhost:8080)
2017-01-06 00:20:45.908 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: not authorized
2017-01-06 00:20:46.406 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:20:46.408 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:51.432 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:20:51.434 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:20:55.175 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-06 00:20:56.921 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 78: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:20:58.463 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-01-06 00:20:58.649 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2017-01-06 00:21:01.665 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 3e416cf6-5a39-4ffd-a0f3-188f2f6627d7, base URL = http://localhost:8080)
2017-01-06 00:21:02.014 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=77, callback=64, payload=4D 06 60 0D 01 01 33 01 
2017-01-06 00:21:02.506 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: not authorized
2017-01-06 00:21:04.946 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-06 00:21:07.039 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:21:07.041 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:10.962 [INFO ] [egram.internal.TelegramActionService] - Bot jucs_openhab_bot loaded from config file
2017-01-06 00:21:11.010 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-01-06 00:21:11.090 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Shutting down my.openHAB service connection
2017-01-06 00:21:11.206 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Disconnected from my.openHAB service (UUID = 3e416cf6-5a39-4ffd-a0f3-188f2f6627d7, base URL = http://localhost:8080)
2017-01-06 00:21:11.436 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-01-06 00:21:11.796 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: not authorized
2017-01-06 00:21:12.072 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:21:12.073 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:17.091 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:21:17.093 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:19.798 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-01-06 00:21:20.039 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-01-06 00:21:20.687 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-01-06 00:21:20.746 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-01-06 00:21:22.113 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=77, callback=72, payload=4D 06 60 0D 01 01 33 01 
2017-01-06 00:21:23.508 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2017-01-06 00:21:24.757 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: not authorized
2017-01-06 00:21:27.142 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:21:27.144 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:28.850 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-06 00:21:29.952 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-06 00:21:30.916 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 3e416cf6-5a39-4ffd-a0f3-188f2f6627d7, base URL = http://localhost:8080)
2017-01-06 00:21:31.627 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-01-06 00:21:32.161 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:21:32.164 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:32.337 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2017-01-06 00:21:33.242 [INFO ] [egram.internal.TelegramActionService] - Bot jucs_openhab_bot loaded from config file
2017-01-06 00:21:37.182 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:21:37.184 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:42.203 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=77, callback=79, payload=4D 06 60 0D 01 01 33 01 
2017-01-06 00:21:47.221 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:21:47.223 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:52.241 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:21:52.244 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:21:57.261 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-06 00:21:57.263 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:22:02.283 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=77, callback=82, payload=4D 06 60 0D 01 01 33 01 
2017-01-06 00:22:06.484 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 20: Node is DEAD. Dropping message.
2017-01-06 00:22:10.674 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 20: Node is DEAD. Dropping message.
2017-01-06 00:22:14.773 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Node is DEAD. Dropping message.
2017-01-06 00:22:18.913 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Node is DEAD. Dropping message.
2017-01-06 00:22:23.044 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Node is DEAD. Dropping message.
2017-01-06 00:22:27.334 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Node is DEAD. Dropping message.
2017-01-06 00:22:31.534 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Node is DEAD. Dropping message.
2017-01-06 00:22:35.664 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Node is DEAD. Dropping message.
2017-01-06 00:22:39.824 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 20: Node is DEAD. Dropping message.
2017-01-06 00:22:43.964 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Node is DEAD. Dropping message.
2017-01-06 00:22:48.214 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Node is DEAD. Dropping message.
2017-01-06 00:22:52.394 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 20: Node is DEAD. Dropping message.
2017-01-06 00:22:57.411 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-06 00:22:57.414 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.
2017-01-06 00:23:00.770 [ERROR] [apache.karaf.shell.support.ShellUtil] - Exception caught while executing command
java.lang.IllegalArgumentException: No enum constant org.apache.karaf.log.core.Level.OPENHAB.BINDING.ZWAVE
        at java.lang.Enum.valueOf(Enum.java:238)[:1.8.0_111]
        at org.apache.karaf.log.core.Level.valueOf(Level.java:23)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:125)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.log.command.SetLogLevel.execute(SetLogLevel.java:48)[48:org.apache.karaf.log.core:4.0.8]
        at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[53:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[53:org.apache.karaf.shell.core:4.0.8]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2017-01-06 00:23:02.432 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 77: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-06 00:23:02.434 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 77: Got an error while sending data. Resending message.

It talks about a lot of communication errors with node 77, however the dimmer does in fact work. I’ve also tried your command on the console, however I got an error:

openhab> log:set openhab.binding.zwave
Error executing command: No enum constant org.apache.karaf.log.core.Level.OPENHAB.BINDING.ZWAVE

chris · January 5, 2017, 11:27pm

No - starting with the debug script doesn’t change the logging - it adds a debug service, but that’s not what you need. You need to do what I said earlier via the console.

Julian_Kranz · January 5, 2017, 11:28pm

I’ve tried, it gives me an error:

openhab> log:set openhab.binding.zwave
Error executing command: No enum constant org.apache.karaf.log.core.Level.OPENHAB.BINDING.ZWAVE

chris · January 5, 2017, 11:30pm

Sorry - should be log:set debug org.openhab.binding.zwave

Julian_Kranz · January 5, 2017, 11:40pm

Ah; this time it didn’t print any error. I did it right after restarting, just after I saw the console. However, I didn’t get any further message from the Z-Wave binding… I still only see ERROR, WARN and INFO messages, like before.

Is there a separate debug log file?

Julian_Kranz · January 6, 2017, 12:01am

I’ve now set the overall log level to debug; that changed something! Here is the result (as XML, I’m not allowed to upload .log files):

openhab.log_1.xml (876.4 KB)
openhab.log_2.xml (900.8 KB)

chris · January 6, 2017, 9:36am

Sorry - there’s still no debug information from the zwave binding in these logs…

Julian_Kranz · January 6, 2017, 1:23pm

Ok, but why? I’ve used your command and I’ve even set the default log level to DEBUG…

chris · January 6, 2017, 1:26pm

I’m not sure - there is debug information in the log - just not from the zwave binding. It’s almost like you’ve enabled it for everything except zwave…

Julian_Kranz · January 6, 2017, 2:06pm

No idea as to why

DigitalBites · April 7, 2017, 12:29am

@chris

I can add a little bit as I’m having a similar issue with the exact same device. I’ve got some debug logs for this as well.

Device is securely included to the wave network. There is 1 controller and 2 nodes. “node 2” is a battery device and it will eventually show up as “online” w/o any issues. “Node 4” is a AEOTEC Smart Dimmer ZW099-A02 (same as initial poster). It includes fine and I do see energy consumption, state updates and on/off/dimmer control just fine.

The binding never creates the node4.xml file and it’s always “stuck” at STATIC_VALUES state. In addition the firmware always shows 0.0, and some other strange things like:

Manufacturer 0086 AEON Labs
Type / ID 0103:0063
Firmware Version0.0
Z-Wave Plus Node TypeLIGHT_DIMMER_SWITCH
Basic Class NOT_KNOWN
Generic Class NOT_KNOWN
Specific Class NOT_USED

Thinking the debug logs and description might help both @Julian_Kranz and me out. Any ideas??

zwave.log.xml (620.3 KB)

edit…
Using OpenHAB2 snapshot build from 2017-03-31 (was happening from an earlier build but updated to latest)
Using Z-Wave build - 2.1.0.201703310852 | ZWave Binding

chris · April 7, 2017, 6:23am

The following two statements are incompatible…

The current snapshot of OH2 ZWave binding doesn’t support security. If you have tried to securely include the device, then it won’t work properly. I would suggest to exclude it and re-include without security (ie disable security in the controller).

DigitalBites · April 7, 2017, 11:46pm

Thanks for the advice @chris. I have completed the steps and have the same symptoms. I did notice this which might help troubleshoot… I first enabled “inclusion” and added the device and it worked fine (went past STATIC_VALUES) and was “online”. When restarting the binding, it is now stuck where it was before not moving beyond STATIC_VALUES. the new log here includes both situations. First inclusion and after restarting the binding.

the device in question is now “node5”

This is a ZIP FILE - plz rename extension to .zip - it was too big to upload (just over 1024k )
zwave.log.xml (68.4 KB)

Applicable last lines:

2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of MULTI_INSTANCE_ASSOCIATION
2017-04-07 16:22:20.098 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 5: Creating new message for command MULTI_ASSOCIATIONCMD_GROUPINGSGET
2017-04-07 16:22:20.098 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3D 00 00 02
2017-04-07 16:22:20.098 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=61, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking CLOCK
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking CONFIGURATION
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking DEVICE_RESET_LOCALLY
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking SWITCH_ALL
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - found    SWITCH_ALL
2017-04-07 16:22:20.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of SWITCH_ALL
2017-04-07 16:22:20.098 [DEBUG] [mandclass.ZWaveSwitchAllCommandClass] - NODE 5: Creating new message for command SWITCH_ALL_GET
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking METER
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - found    METER
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of METER
2017-04-07 16:22:20.099 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_SUPPORTED_GET
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking ASSOCIATION_GROUP_INFO
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - found    ASSOCIATION_GROUP_INFO
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of ASSOCIATION_GROUP_INFO
2017-04-07 16:22:20.099 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 5: Initialising association group info - 1 groups known
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking COLOR
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - found    COLOR
2017-04-07 16:22:20.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of COLOR
2017-04-07 16:22:20.099 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 5: Creating new message for application command SWITCH_COLOR_SUPPORTED_GET
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking VERSION
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking BASIC
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - checking ASSOCIATION
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - found    ASSOCIATION
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Found 1 instances of ASSOCIATION
2017-04-07 16:22:20.100 [DEBUG] [ndclass.ZWaveAssociationCommandClass] - NODE 5: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2017-04-07 16:22:20.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: STATIC_VALUES - queued 13 frames
2017-04-07 16:22:25.006 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Timeout while sending message. Requeueing - 2 attempts left!
2017-04-07 16:22:25.007 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Got an error while sending data. Resending message.
2017-04-07 16:22:25.007 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-04-07 16:22:25.007 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-04-07 16:22:25.007 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 3E A6
2017-04-07 16:22:25.007 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 3E A6
2017-04-07 16:22:25.015 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-04-07 16:22:25.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:25.016 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-04-07 16:22:25.016 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-04-07 16:22:25.016 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-04-07 16:22:25.016 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
2017-04-07 16:22:25.031 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 3E 00 00 02 D7
2017-04-07 16:22:25.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:25.032 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 3E 00 00 02 00 00 D9
2017-04-07 16:22:25.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 3E 00 00 02 00 00 D9
2017-04-07 16:22:25.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3E 00 00 02
2017-04-07 16:22:25.032 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 62, Status = Transmission complete and ACK received(0)
2017-04-07 16:22:25.033 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, callback=62, payload=05 06 60 0D 01 01 33 01
2017-04-07 16:22:25.033 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3E 00 00 02
2017-04-07 16:22:25.033 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=62, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-04-07 16:22:30.008 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Timeout while sending message. Requeueing - 1 attempts left!
2017-04-07 16:22:30.008 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Got an error while sending data. Resending message.
2017-04-07 16:22:30.008 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-04-07 16:22:30.008 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-04-07 16:22:30.008 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 3F A7
2017-04-07 16:22:30.008 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 3F A7
2017-04-07 16:22:30.016 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-04-07 16:22:30.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:30.017 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-04-07 16:22:30.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-04-07 16:22:30.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-04-07 16:22:30.017 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
2017-04-07 16:22:30.033 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 3F 00 00 03 D7
2017-04-07 16:22:30.033 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:30.033 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 3F 00 00 03 00 00 D9
2017-04-07 16:22:30.034 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 3F 00 00 03 00 00 D9
2017-04-07 16:22:30.034 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 03
2017-04-07 16:22:30.034 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 63, Status = Transmission complete and ACK received(0)
2017-04-07 16:22:30.034 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, callback=63, payload=05 06 60 0D 01 01 33 01
2017-04-07 16:22:30.034 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 03
2017-04-07 16:22:30.034 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=63, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-04-07 16:22:35.009 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Timeout while sending message. Requeueing - 0 attempts left!
2017-04-07 16:22:35.009 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Got an error while sending data. Resending message.
2017-04-07 16:22:35.009 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-04-07 16:22:35.009 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-04-07 16:22:35.010 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 40 D8
2017-04-07 16:22:35.010 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0D 00 13 05 06 60 0D 01 01 33 01 25 40 D8
2017-04-07 16:22:35.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-04-07 16:22:35.018 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:35.018 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-04-07 16:22:35.018 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-04-07 16:22:35.019 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-04-07 16:22:35.019 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
2017-04-07 16:22:35.034 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 40 00 00 02 A9
2017-04-07 16:22:35.035 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-07 16:22:35.035 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 40 00 00 02 00 00 A7
2017-04-07 16:22:35.035 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 40 00 00 02 00 00 A7
2017-04-07 16:22:35.035 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=40 00 00 02
2017-04-07 16:22:35.035 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 64, Status = Transmission complete and ACK received(0)
2017-04-07 16:22:35.035 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, callback=64, payload=05 06 60 0D 01 01 33 01
2017-04-07 16:22:35.035 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=40 00 00 02
2017-04-07 16:22:35.035 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=64, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-04-07 16:22:40.010 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=5, callback=64, payload=05 06 60 0D 01 01 33 01

chris · April 8, 2017, 10:10am

The problem is that the device states that it supports the color command class on all endpoints, but then when polled, it doesn’t respond.

I’m not really sure why this device even supports multiple endpoints (2) - I’ll ask Aeon about this, but there’s probably a workaround I can add to fix this in the database.

DigitalBites · April 12, 2017, 3:02am

That would be great. Glad to compile/test whatever. Thanks for the help!!

BerniMurphy · August 17, 2017, 8:50pm

was there any progress here?

I guess the color command is used for the RGB light ring the device has to show the operational state (off/ on = power consumption (green to red))
The RGB value for off should also be settable