Stuck on Associations

jwilliams · September 12, 2019, 11:40pm

Hello Community,

I recently added an Eaton Z-Wave Dimmer to my Aeotec Z-Wave controller, and on startup is always remains stuck at the “Associations” stage. When I look at the logs, it keeps looping through the same thing. Here is a snippet of the log:

2019-09-12 19:37:24.100 Info, Node074, Association::Set - Adding node 1 to group 255 of node 74
2019-09-12 19:37:24.100 Detail, Node074, Queuing (Send) AssociationCmd_Set (Node=74): 0x01, 0x0b, 0x00, 0x13, 0x4a, 0x04, 0x85, 0x01, 0xff, 0x01, 0x25, 0x5a, 0xac
2019-09-12 19:37:24.100 Info, Node074, Get Associations for group 255 of node 74
2019-09-12 19:37:24.100 Detail, Node074, Queuing (Send) AssociationCmd_Get (Node=74): 0x01, 0x0a, 0x00, 0x13, 0x4a, 0x03, 0x85, 0x02, 0xff, 0x25, 0x5b, 0xa9
2019-09-12 19:37:24.100 Detail, Node074,   Expected reply and command class was received
2019-09-12 19:37:24.100 Detail, Node074,   Message transaction complete
2019-09-12 19:37:24.100 Detail,
2019-09-12 19:37:24.100 Detail, Node074, Removing current message
2019-09-12 19:37:24.100 Detail,
2019-09-12 19:37:24.100 Info, Node074, Sending (Send) message (Callback ID=0x9b, Expected Reply=0x13) - AssociationCmd_Set (Node=74): 0x01, 0x0b, 0x00, 0x13, 0x4a, 0x04, 0x85, 0x01, 0xff, 0x01, 0x25, 0x9b, 0x6d
2019-09-12 19:37:24.109 Detail, Node074,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-09-12 19:37:24.109 Detail, Node074,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 19:37:24.128 Detail, Node074,   Received: 0x01, 0x07, 0x00, 0x13, 0x9b, 0x00, 0x00, 0x03, 0x73
2019-09-12 19:37:24.129 Detail, Node074,   ZW_SEND_DATA Request with callback ID 0x9b received (expected 0x9b)
2019-09-12 19:37:24.129 Info, Node074, Request RTT 28 Average Request RTT 27
2019-09-12 19:37:24.129 Detail,   Expected callbackId was received
2019-09-12 19:37:24.129 Detail,   Expected reply was received
2019-09-12 19:37:24.129 Detail,   Message transaction complete
2019-09-12 19:37:24.129 Detail,
2019-09-12 19:37:24.129 Detail, Node074, Removing current message
2019-09-12 19:37:24.129 Detail,
2019-09-12 19:37:24.129 Info, Node074, Sending (Send) message (Callback ID=0x9c, Expected Reply=0x04) - AssociationCmd_Get (Node=74): 0x01, 0x0a, 0x00, 0x13, 0x4a, 0x03, 0x85, 0x02, 0xff, 0x25, 0x9c, 0x6e
2019-09-12 19:37:24.138 Detail, Node074,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-09-12 19:37:24.138 Detail, Node074,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 19:37:24.155 Detail, Node074,   Received: 0x01, 0x07, 0x00, 0x13, 0x9c, 0x00, 0x00, 0x03, 0x74
2019-09-12 19:37:24.155 Detail, Node074,   ZW_SEND_DATA Request with callback ID 0x9c received (expected 0x9c)
2019-09-12 19:37:24.155 Info, Node074, Request RTT 26 Average Request RTT 26
2019-09-12 19:37:24.155 Detail,   Expected callbackId was received
2019-09-12 19:37:24.166 Detail, Node074,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x4a, 0x05, 0x85, 0x03, 0xff, 0x00, 0x00, 0xc6
2019-09-12 19:37:24.166 Detail,
2019-09-12 19:37:24.166 Info, Node074, Response RTT 37 Average Response RTT 37
2019-09-12 19:37:24.167 Info, Node074, Max associations for node 74, group 255 is zero.  Querying associations for this node is complete.
2019-09-12 19:37:24.167 Info, Node074, Adding the controller to group 255 (Group #255) of node 74
2019-09-12 19:37:24.167 Info, Node074, Association::Set - Adding node 1 to group 255 of node 74
2019-09-12 19:37:24.167 Detail, Node074, Queuing (Send) AssociationCmd_Set (Node=74): 0x01, 0x0b, 0x00, 0x13, 0x4a, 0x04, 0x85, 0x01, 0xff, 0x01, 0x25, 0x5c, 0xaa
2019-09-12 19:37:24.167 Info, Node074, Get Associations for group 255 of node 74
2019-09-12 19:37:24.167 Detail, Node074, Queuing (Send) AssociationCmd_Get (Node=74): 0x01, 0x0a, 0x00, 0x13, 0x4a, 0x03, 0x85, 0x02, 0xff, 0x25, 0x5d, 0xaf
2019-09-12 19:37:24.167 Detail, Node074,   Expected reply and command class was received
2019-09-12 19:37:24.167 Detail, Node074,   Message transaction complete
2019-09-12 19:37:24.167 Detail,
2019-09-12 19:37:24.167 Detail, Node074, Removing current message
2019-09-12 19:37:24.167 Detail,
2019-09-12 19:37:24.167 Info, Node074, Sending (Send) message (Callback ID=0x9d, Expected Reply=0x13) - AssociationCmd_Set (Node=74): 0x01, 0x0b, 0x00, 0x13, 0x4a, 0x04, 0x85, 0x01, 0xff, 0x01, 0x25, 0x9d, 0x6b
2019-09-12 19:37:24.176 Detail, Node074,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-09-12 19:37:24.176 Detail, Node074,   ZW_SEND_DATA delivered to Z-Wave stack

The offending node is Node 74. Has anybody seen this before? If I remove the device by cutting power, everything goes back to normal. I have also tried removing and re-adding it.

Help is appreciated!

Jason

freshcoast · September 13, 2019, 5:07am

If you are able, use the Z-Wave Control Panel or the service call to see if the dimmer is part of the broadcast group (group 255) and remove it if so. Instructions here:

jwilliams · September 13, 2019, 4:25pm

Thanks @freshcoast. In ZCP I do see it in group 255, but I can’t figure out how to remove it. I create a script using the zwave.change_association service like this:

{
  "association": "remove",
  "group": 1,
  "node_id": 74,
  "target_node_id": 255
}

but it doesn’t remove the node. My Zwave service won’t finishing starting until I disable the node, so I did that, let it finish starting, then turned it back on and ran the script.

Here is a screenshot:

There is no remove button. Do you have any suggestions?

freshcoast · September 13, 2019, 8:02pm

Actually, looking closer, that is a bit different. What’s the model number of the switch? I found a similar problem with a Cooper switch.

freshcoast · September 13, 2019, 8:04pm

Also you might post the XML for the node so we can see what the association group configuration looks like.

jwilliams · September 13, 2019, 8:43pm

Hi @freshcoast,

I saw that too, and yes this is a Cooper switch (branded as Eaton). The model # is RF9540-N. Here is the XML for that node. I did try changing it in the XML, but I think its cached in the controller.

	<Node id="74" name="" location="" basic="4" generic="17" specific="4" type="Multilevel Scene Switch" listening="true" frequentListening="false" beaming="true" routing="true" max_baud_rate="40000" version="4" query_stage="CacheLoad">
		<Manufacturer id="1a" name="Eaton">
			<Product type="4449" id="101" name="RF9540-N All Load Dimmer Light Switch" />
		</Manufacturer>
		<CommandClasses>
			<CommandClass id="32" name="COMMAND_CLASS_BASIC" version="1" request_flags="4" mapping="38">
				<Instance index="1" />
			</CommandClass>
			<CommandClass id="38" name="COMMAND_CLASS_SWITCH_MULTILEVEL" version="2" innif="true">
				<Instance index="1" />
				<Value type="byte" genre="user" instance="1" index="0" label="Level" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
				<Value type="button" genre="user" instance="1" index="1" label="Bright" units="" read_only="false" write_only="true" verify_changes="false" poll_intensity="0" min="0" max="0" />
				<Value type="button" genre="user" instance="1" index="2" label="Dim" units="" read_only="false" write_only="true" verify_changes="false" poll_intensity="0" min="0" max="0" />
				<Value type="bool" genre="system" instance="1" index="3" label="Ignore Start Level" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" value="True" />
				<Value type="byte" genre="system" instance="1" index="4" label="Start Level" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
				<Value type="byte" genre="system" instance="1" index="5" label="Dimming Duration" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="255" />
			</CommandClass>
			<CommandClass id="39" name="COMMAND_CLASS_SWITCH_ALL" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="list" genre="system" instance="1" index="0" label="Switch All" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" vindex="0" size="1">
					<Item label="Disabled" value="0" />
					<Item label="Off Enabled" value="1" />
					<Item label="On Enabled" value="2" />
					<Item label="On and Off Enabled" value="255" />
				</Value>
			</CommandClass>
			<CommandClass id="43" name="COMMAND_CLASS_SCENE_ACTIVATION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
			</CommandClass>
			<CommandClass id="112" name="COMMAND_CLASS_CONFIGURATION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="byte" genre="config" instance="1" index="1" label="Delayed OFF time" units="seconds" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0">
					<Help>The configuration value is a signed single byte number. This value may represent a value with no units or may represent a value such as time. 0 to 127 (decimal) represents 0 to 127 seconds of time. -128 to -1 (negative decimal numbers) represents 128 to 255 seconds as calculated by this formula. Config value = desired time in seconds (or desired value) -256 For an example of 172 seconds: config value = 172 - 256 = -84 (decimal) or 0xAC (hex)</Help>
				</Value>
				<Value type="byte" genre="config" instance="1" index="2" label="Panic ON time" units="seconds" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="1" max="255" value="0">
					<Help>The amount of time in seconds the switch will turn on for when panic mode is trigered. The configuration value is a signed single byte number. This value may represent a value with no units or may represent a value such as time. 0 to 127 (decimal) represents 0 to 127 seconds of time. -128 to -1 (negative decimal numbers) represents 128 to 255 seconds as calculated by this formula. Config value = desired time in seconds (or desired value) -256 For an example of 172 seconds: config value = 172 - 256 = -84 (decimal) or 0xAC (hex)</Help>
				</Value>
				<Value type="byte" genre="config" instance="1" index="3" label="Panic OFF time" units="seconds" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="1" max="255" value="0">
					<Help>The amount of time in seconds the switch will turn off for when panic mode is triggered. The configuration value is a signed single byte number. This value may represent a value with no units or may represent a value such as time. 0 to 127 (decimal) represents 0 to 127 seconds of time. -128 to -1 (negative decimal numbers) represents 128 to 255 seconds as calculated by this formula. Config value = desired time in seconds (or desired value) -256 For an example of 172 seconds: config value = 172 - 256 = -84 (decimal) or 0xAC (hex)</Help>
				</Value>
				<Value type="byte" genre="config" instance="1" index="4" label="Basic set value" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="1" max="255" value="0">
					<Help>Setting this to anything other than 0 will cause the value to be transmitted to devices in the association group when the switch is triggered. A setting other than 0 will likely result in undesired operation</Help>
				</Value>
				<Value type="list" genre="config" instance="1" index="5" label="Power Up State" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="1" max="3" vindex="2" size="1">
					<Help>Power up state of the device</Help>
					<Item label="OFF" value="1" />
					<Item label="ON" value="2" />
					<Item label="Last state" value="3" />
				</Value>
				<Value type="list" genre="config" instance="1" index="6" label="Panic mode enable" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="1" max="2" vindex="0" size="1">
					<Help>Enables this switch to participate in panic mode</Help>
					<Item label="OFF" value="1" />
					<Item label="ON" value="2" />
				</Value>
				<Value type="byte" genre="config" instance="1" index="7" label="Dimmer Ramp Time" units="seconds" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0">
					<Help>The amount of time in seconds the switch will take to reach the desired dim level. The configuration value is a signed single byte number. This value may represent a value with no units or may represent a value such as time. 0 to 127 (decimal) represents 0 to 127 seconds of time. -128 to -1 (negative decimal numbers) represents 128 to 255 seconds as calculated by this formula. Config value = desired time in seconds (or desired value) -256 For an example of 172 seconds: config value = 172 - 256 = -84 (decimal) or 0xAC (hex)</Help>
				</Value>
				<Value type="list" genre="config" instance="1" index="8" label="Kickstart / Rapid Start" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="1" vindex="0" size="1">
					<Help>Ensures that LED / CFL bulbs turn on when the preset dim level is low. Enabling this feature may cause the lights brightness to momentarily be bright when the switch is turned on before reducing in brightness to desired level</Help>
					<Item label="disable" value="0" />
					<Item label="enable" value="1" />
				</Value>
				<Value type="byte" genre="config" instance="1" index="11" label="Minimum Dimmer Level" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="4" max="99" value="4">
					<Help>The minimum dim level the switch will allow. The minimum level must always be at least 13 below the maximum level.</Help>
				</Value>
				<Value type="byte" genre="config" instance="1" index="12" label="Maximum Dimmer Level" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="4" max="99" value="99">
					<Help>The maximum dim level the switch will allow. The maximum level must always be at least 13 above the minimum level.</Help>
				</Value>
			</CommandClass>
			<CommandClass id="113" name="COMMAND_CLASS_ALARM" version="1" request_flags="2" innif="true">
				<Instance index="1" />
				<Value type="byte" genre="user" instance="1" index="0" label="Alarm Type" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
				<Value type="byte" genre="user" instance="1" index="1" label="Alarm Level" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
			</CommandClass>
			<CommandClass id="114" name="COMMAND_CLASS_MANUFACTURER_SPECIFIC" version="1" request_flags="4" innif="true">
				<Instance index="1" />
			</CommandClass>
			<CommandClass id="115" name="COMMAND_CLASS_POWERLEVEL" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="list" genre="system" instance="1" index="0" label="Powerlevel" units="dB" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" vindex="0" size="1">
					<Item label="Normal" value="0" />
					<Item label="-1dB" value="1" />
					<Item label="-2dB" value="2" />
					<Item label="-3dB" value="3" />
					<Item label="-4dB" value="4" />
					<Item label="-5dB" value="5" />
					<Item label="-6dB" value="6" />
					<Item label="-7dB" value="7" />
					<Item label="-8dB" value="8" />
					<Item label="-9dB" value="9" />
				</Value>
				<Value type="byte" genre="system" instance="1" index="1" label="Timeout" units="seconds" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
				<Value type="button" genre="system" instance="1" index="2" label="Set Powerlevel" units="" read_only="false" write_only="true" verify_changes="false" poll_intensity="0" min="0" max="0" />
				<Value type="byte" genre="system" instance="1" index="3" label="Test Node" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
				<Value type="list" genre="system" instance="1" index="4" label="Test Powerlevel" units="dB" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" vindex="0" size="1">
					<Item label="Normal" value="0" />
					<Item label="-1dB" value="1" />
					<Item label="-2dB" value="2" />
					<Item label="-3dB" value="3" />
					<Item label="-4dB" value="4" />
					<Item label="-5dB" value="5" />
					<Item label="-6dB" value="6" />
					<Item label="-7dB" value="7" />
					<Item label="-8dB" value="8" />
					<Item label="-9dB" value="9" />
				</Value>
				<Value type="short" genre="system" instance="1" index="5" label="Frame Count" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="-32768" max="32767" value="0" />
				<Value type="button" genre="system" instance="1" index="6" label="Test" units="" read_only="false" write_only="true" verify_changes="false" poll_intensity="0" min="0" max="0" />
				<Value type="button" genre="system" instance="1" index="7" label="Report" units="" read_only="false" write_only="true" verify_changes="false" poll_intensity="0" min="0" max="0" />
				<Value type="list" genre="system" instance="1" index="8" label="Test Status" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" vindex="0" size="1">
					<Item label="Failed" value="0" />
					<Item label="Success" value="1" />
					<Item label="In Progress" value="2" />
				</Value>
				<Value type="short" genre="system" instance="1" index="9" label="Acked Frames" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="-32768" max="32767" value="0" />
			</CommandClass>
			<CommandClass id="117" name="COMMAND_CLASS_PROTECTION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="list" genre="system" instance="1" index="0" label="Protection" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" vindex="0" size="1">
					<Item label="Unprotected" value="0" />
					<Item label="Protection by Sequence" value="1" />
					<Item label="No Operation Possible" value="2" />
				</Value>
			</CommandClass>
			<CommandClass id="119" name="COMMAND_CLASS_NODE_NAMING" version="1" request_flags="4" innif="true">
				<Instance index="1" />
			</CommandClass>
			<CommandClass id="133" name="COMMAND_CLASS_ASSOCIATION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Associations num_groups="1">
					<Group index="1" max_associations="5" label="Group #1" auto="true">
						<Node id="1" />
						<Node id="73" />
					</Group>
					<Group index="255" max_associations="1" label="Group #255" auto="true" />
				</Associations>
			</CommandClass>
			<CommandClass id="134" name="COMMAND_CLASS_VERSION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="string" genre="system" instance="1" index="0" label="Library Version" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" value="3" />
				<Value type="string" genre="system" instance="1" index="1" label="Protocol Version" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" value="3.67" />
				<Value type="string" genre="system" instance="1" index="2" label="Application Version" units="" read_only="true" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="0" value="1.02" />
			</CommandClass>
			<CommandClass id="135" name="COMMAND_CLASS_INDICATOR" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Value type="byte" genre="user" instance="1" index="0" label="Indicator" units="" read_only="false" write_only="false" verify_changes="false" poll_intensity="0" min="0" max="255" value="0" />
			</CommandClass>
		</CommandClasses>
	</Node>
</Driver>

freshcoast · September 13, 2019, 9:31pm

This says group 255 allows 0 associations. If that’s being reported by the device, then adding a node to the group is going to fail. That could be why OZW is looping, if it is attempting to add the node to the group until successful. That sounds like the opposite of the referenced bug, in this case group 1 is valid but group 255 is not. You might try doing the same thing as in that issue but with group 255. Exclude the node from the controller (can you?), stop Home Assistant, modify the device XML file and remove group 255, start Home Assistant, then re-include it.

Find the file RF9540-N.xml in your Python installation. Replace the Association Groups XML with the following:

	<CommandClass id="133">
		<Associations num_groups="1">
        	        <Group index="1" max_associations="5" label="Group #1" />
		</Associations>
	</CommandClass>

It just removes group 255 from the list of possible groups which should stop OZW from trying to add the controller to it.

Supposedly the device supports group 255, but if the other device model was buggy, this could be too.

You might be able to get away with just modifying the zwcfg*.xml file first, and make the same change. If the group actually has no associations, there’s nothing stored anywhere. Make sure you stop Home Assistant before modifying the file. Just remove the group 255 entry.

			<CommandClass id="133" name="COMMAND_CLASS_ASSOCIATION" version="1" request_flags="4" innif="true">
				<Instance index="1" />
				<Associations num_groups="1">
					<Group index="1" max_associations="5" label="Group #1" auto="true">
						<Node id="1" />
						<Node id="73" />
					</Group>
				</Associations>
			</CommandClass>

Did you actually associate node 73 yourself?

jwilliams · September 15, 2019, 7:09pm

I did add node 73, this type of switch is paired with a battery operated switch so you can control it remotely.

I can’t find RF9540-N.xml anywhere. I’m using hass.io, so I’m not sure which folder would house these files. I looked in the deps folder, but it is empty.

If I remove that line from the zwcfg file, the node disappears from the UI. Any guidance is appreciated.

UPDATE: I renamed the node in Entity Management and now it appears! The group is now removed and the Zwave network starts.

Thanks so much for your help @freshcoast!