Two SP600 devices - one reports power, the other doesn't.

[davet2001]

What happened

Added two SP600 sockets to my network.
Only one of them reports power levels.

2019-11-16T21:55:33: MQTT publish: topic 'zigbee2mqtt/salus_socket1', payload '{"state":"OFF","linkquality":57,"power":1}'

2019-11-16T21:54:13: MQTT publish: topic 'zigbee2mqtt/salus_socket2', payload '{"state":"ON","linkquality":18}'

What did you expect to happen

Both visible on the network, both report on/off status, link quality and power

How to reproduce it (minimal and precise)

Connect both devices to network.
Turn the socket off via homeassistant.
Turn the socket on via homeassistant.
Repeat for second device.
Observe the zigbee2mqtt logs.

Debug Info

zigbee2mqtt version:
1.6.0

CC253X firmware version:
20190608

Edit: it seems to be significant that the working device was added to zigbee2mqtt and database.db while running an older version of zigbee2mqtt

[davet2001]

I did some debugging to help narrow down.
The working device is 0x001e5e0902145ebf
The non-working device is 0x001e5e090215f14f

I noticed that they appear quite differently in database.db
Working device:

{
    "id": 10,
    "type": "Router",
    "ieeeAddr": "0x001e5e0902145ebf",
    "nwkAddr": 18388,
    "manufId": 4216,
    "manufName": "Computime",
    "powerSource": "Mains (single phase)",
    "modelId": "SP600",
    "epList": [9],
    "endpoints": {
        "9": {
            "profId": 260,
            "epId": 9,
            "devId": 81,
            "inClusterList": [0, 1, 3, 4, 5, 6, 1026, 1794, 64513],
            "outClusterList": [25],
            "clusters": {
                "64513": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {}
                },
                "genBasic": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "zclVersion": 1,
                        "appVersion": 20,
                        "stackVersion": 2,
                        "hwVersion": 2,
                        "manufacturerName": "Computime",
                        "modelId": "SP600",
                        "dateCode": "20160217",
                        "powerSource": 1,
                        "deviceEnabled": 1
                    }
                },
                "genPowerCfg": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "mainsVoltage": 2440
                    }
                },
                "genIdentify": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "identifyTime": 0
                    }
                },
                "genGroups": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "nameSupport": 1
                    }
                },
                "genScenes": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "count": 0,
                        "currentScene": 0,
                        "currentGroup": 0,
                        "sceneValid": 0,
                        "nameSupport": 128
                    }
                },
                "genOnOff": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "onOff": 1
                    }
                },
                "genOta": {
                    "dir": {
                        "value": 2
                    },
                    "attributes": {}
                },
                "msTemperatureMeasurement": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "measuredValue": 2100,
                        "minMeasuredValue": 0,
                        "maxMeasuredValue": 8500
                    }
                },
                "seMetering": {
                    "dir": {
                        "value": 1
                    },
                    "attributes": {
                        "currentSummDelivered": {
                            "0": 0,
                            "1": 0
                        },
                        "currentSummReceived": {
                            "0": 0,
                            "1": 0
                        },
                        "defaultUpdatePeriod": 12,
                        "fastPollUpdatePeriod": 1,
                        "status": 0,
                        "unitOfMeasure": 0,
                        "multiplier": 1,
                        "divisor": 10000,
                        "summaFormatting": 0,
                        "demandFormatting": 0,
                        "historicalConsumpFormatting": 0,
                        "meteringDeviceType": 0,
                        "instantaneousDemand": 20
                    }
                }
            },
            "binds": [{
                    "cluster": 6,
                    "type": "endpoint",
                    "deviceIeeeAddress": "0x00124b0019369374",
                    "endpointID": 1
                }
            ]
        }
    },
    "appVersion": 20,
    "stackVersion": 2,
    "hwVersion": 2,
    "dateCode": "20160217",
    "zclVersion": 1,
    "meta": {
        "configured": 2
    }
}

Non-working device:

{
	"id": 5,
	"type": "Router",
	"ieeeAddr": "0x001e5e090215f14f",
	"nwkAddr": 835,
	"manufId": 4216,
	"manufName": "Computime",
	"powerSource": "Mains (single phase)",
	"modelId": "SP600",
	"epList": [9],
	"endpoints": {
		"9": {
			"profId": 260,
			"epId": 9,
			"devId": 81,
			"inClusterList": [0, 1, 3, 4, 5, 6, 1026, 1794, 64513],
			"outClusterList": [25],
			"clusters": {
				"genBasic": {
					"attributes": {
						"modelId": "SP600",
						"manufacturerName": "Computime",
						"powerSource": 1,
						"zclVersion": 1,
						"appVersion": 25,
						"stackVersion": 2,
						"hwVersion": 2,
						"dateCode": "20160331"
					}
				},
				"seMetering": {
					"attributes": {
						"multiplier": 1,
						"divisor": 10000
					}
				}
			},
			"binds": [{
					"cluster": 6,
					"type": "endpoint",
					"deviceIeeeAddress": "0x00124b0019369374",
					"endpointID": 1
				}
			]
		}
	},
	"appVersion": 25,
	"stackVersion": 2,
	"hwVersion": 2,
	"dateCode": "20160331",
	"zclVersion": 1,
	"interviewCompleted": true,
	"meta": {
		"configured": 2
	}
}

When they are reporting status, they both seem to start with a smilar 5 byte data packet:

Working device:

zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":18388,"srcendpoint":9,"dstendpoint":1,"wasbroadcast":0,"linkquality":47,"securityuse":0,"timestamp":7910580,"transseqnumber":0,"len":5,"data":{"type":"Buffer","data":[8,7,11,1,0]}} +83ms

2019-11-16T17:06:20: MQTT publish: topic 'zigbee2mqtt/salus_socket1', payload '{"state":"ON","linkquality":47,"power":0}'

...

Non-working device:

zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":47815,"srcendpoint":9,"dstendpoint":1,"wasbroadcast":0,"linkquality":23,"securityuse":0,"timestamp":7519024,"transseqnumber":0,"len":5,"data":{"type":"Buffer","data":[8,5,11,1,0]}} +57ms

2019-11-16T17:04:15: MQTT publish: topic 'zigbee2mqtt/salus_socket2', payload '{"state":"ON","linkquality":26}'

Any ideas where I should look next to try to fix this? Happy to try any suggestions out.

[Kryzek]

Try re-pairing after removing non-working device using zigbee2mqtt/bridge/config/remove (https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html for more information). Maybe device did not get configured properly when pairing.

[davet2001]

Try re-pairing after removing non-working device using zigbee2mqtt/bridge/config/remove (https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html for more information). Maybe device did not get configured properly when pairing.

I removed the device entirely from the database.db file and configuration.yaml while zigbee2mqtt was stopped. Not sure if that is the same as above.

Then re-added the device. Same behaviour.

[wjcloudy]

I also have this issue, after a fix was implementing for scaling on the SP600 I had, I bought a further 2, and both of these (a newer firmware in db reported - appversion 25 does not work but appversion 20 does) have a different database structure, and no longer report power. Hoping they've just moved the power reporting, as they advertise this capability still

[davet2001]

Yes, I too have app version 20 as ok and 25 not working.

But I think it should work on both because zigbee2mqtt is receiving a 5 byte data packet in both cases, with almost identical values (see end of debug output lines above).

I am struggling to debug this - I am not familiar with node.js and I am finding it hard to discover the call stack or even the entry point in order to follow the execution.

Is there an IDE or other toolchain that can help, or documentation of the zigbee2mqtt architecture?

[Koenkk]

@davet2001 the 5 byte data packet is from the on/off cluster, this only contains the on/off state of the device. The best way to start debugging is to see if the power measurements are actually send by the device, this can be done by sniffing the traffic: https://www.zigbee2mqtt.io/how_tos/how_to_sniff_zigbee_traffic.html.

[davet2001]

Ok will do. I’ve ordered a second cc2531 to do the sniffing.

[davet2001]

I received my extra cc2531 and started sniffing.
The 'working' device, while powering 7W looks like this (note last value=7):

Frame 4766: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0x47d4
ZigBee Network Layer Data, Dst: 0x0000, Src: 0x47d4
    Frame Control Field: 0x0608, Frame Type: Data, Discover Route: Suppress, Security, Source Route Data
    Destination: 0x0000
    Source: 0x47d4
    Radius: 30
    Sequence Number: 240
    [Extended Source: Computim_09:02:14:5e:bf (00:1e:5e:09:02:14:5e:bf)]
    [Origin: 2]
    Source Route, Length: 0
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 1, Src Endpt: 9
ZigBee Cluster Library Frame, Command: Report Attributes, Seq: 89
    Frame Control Field: Profile-wide (0x08)
    Sequence Number: 89
    Command: Report Attributes (0x0a)
    Attribute Field, Int24: 7
        Attribute: Instantaneous Demand (0x0400)
        Data Type: 24-Bit Signed Integer (0x2a)
        Int24: 7

The non-working device never seems to report 'instantaneous demand', it just reports OnOff:

Frame 5368: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
IEEE 802.15.4 Data, Dst: 0x9b55, Src: 0x5367
ZigBee Network Layer Data, Dst: 0x0000, Src: 0x5367
    Frame Control Field: 0x0608, Frame Type: Data, Discover Route: Suppress, Security, Source Route Data
    Destination: 0x0000
    Source: 0x5367
    Radius: 30
    Sequence Number: 117
    [Extended Source: Computim_09:02:15:f1:4f (00:1e:5e:09:02:15:f1:4f)]
    [Origin: 8]
    Source Route, Length: 1
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 1, Src Endpt: 9
ZigBee Cluster Library Frame, Command: Report Attributes, Seq: 122
    Frame Control Field: Profile-wide (0x08)
    Sequence Number: 122
    Command: Report Attributes (0x0a)
    Attribute Field
        Attribute: OnOff (0x0000)
        Data Type: Boolean (0x10)
        On/off Control: Off (0x00)

Another difference is that *5e:bf is talking all the time, whereas *:f1:4f says almost nothing.
So it definitely seems like they are behaving differently at a data link layer level.

@Koenkk Next question: is the amount and type of things a zigbee device communicates dependent on the coordinator configuration/handshake in some way, or will a device always broadcast all of it's variables using 'report attributes' commands regardless of the network configuration?

If the latter, then I think it means one of these SP600 reports power and the other doesn't.

[davet2001]

Ok, I think I'm getting somewhere now with this.

I completely removed both devices by stopping zigbee2mqtt, then editing configuration.yaml and database.db, deleting the lines for both devices. Then started it up again and re-paired them. Now they both communicate, but neither of them report power.

This time both devices appear in the database.db with a much shorter description (compare with the listing in my first post):

Previously 'working' device - now doesn't report power:

{
   "id":5,
   "type":"Router",
   "ieeeAddr":"0x001e5e0902145ebf",
   "nwkAddr":40450,
   "manufId":4216,
   "manufName":"Computime",
   "powerSource":"Mains (single phase)",
   "modelId":"SP600",
   "epList":[
      9
   ],
   "endpoints":{
      "9":{
         "profId":260,
         "epId":9,
         "devId":81,
         "inClusterList":[
            0,
            1,
            3,
            4,
            5,
            6,
            1026,
            1794,
            64513
         ],
         "outClusterList":[
            25
         ],
         "clusters":{
            "genBasic":{
               "attributes":{
                  "modelId":"SP600",
                  "manufacturerName":"Computime",
                  "powerSource":1,
                  "zclVersion":1,
                  "appVersion":20,
                  "stackVersion":2,
                  "hwVersion":2,
                  "dateCode":"20160217"
               }
            },
            "seMetering":{
               "attributes":{
                  "multiplier":1,
                  "divisor":10000
               }
            }
         },
         "binds":[
            {
               "cluster":6,
               "type":"endpoint",
               "deviceIeeeAddress":"0x00124b0019369374",
               "endpointID":1
            }
         ]
      }
   },
   "appVersion":20,
   "stackVersion":2,
   "hwVersion":2,
   "dateCode":"20160217",
   "zclVersion":1,
   "interviewCompleted":true,
   "meta":{
      "configured":2
   }
}

Previously 'not working' device, still doesn't report power:

{
   "id":10,
   "type":"Router",
   "ieeeAddr":"0x001e5e090215f14f",
   "nwkAddr":34945,
   "manufId":4216,
   "manufName":"Computime",
   "powerSource":"Mains (single phase)",
   "modelId":"SP600",
   "epList":[
      9
   ],
   "endpoints":{
      "9":{
         "profId":260,
         "epId":9,
         "devId":81,
         "inClusterList":[
            0,
            1,
            3,
            4,
            5,
            6,
            1026,
            1794,
            64513
         ],
         "outClusterList":[
            25
         ],
         "clusters":{
            "genBasic":{
               "attributes":{
                  "modelId":"SP600",
                  "manufacturerName":"Computime",
                  "powerSource":1,
                  "zclVersion":1,
                  "appVersion":25,
                  "stackVersion":2,
                  "hwVersion":2,
                  "dateCode":"20160331"
               }
            },
            "seMetering":{
               "attributes":{
                  "multiplier":1,
                  "divisor":10000
               }
            }
         },
         "binds":[
            {
               "cluster":6,
               "type":"endpoint",
               "deviceIeeeAddress":"0x00124b0019369374",
               "endpointID":1
            }
         ]
      }
   },
   "appVersion":25,
   "stackVersion":2,
   "hwVersion":2,
   "dateCode":"20160331",
   "zclVersion":1,
   "interviewCompleted":true,
   "meta":{
      "configured":2
   }
}

So my interpretation is that the old combination of firmware/zigbee2mqtt/zigbee-herdsman/zigbee-herdsman-converters worked for pairing SP600 devices & reporting their power, while the new combination can pair devices but newly paired devices don't report power. Old entries in the database do.

Maybe the problem was introduced with the fix to:
#2233

[wjcloudy]

I can confirm this above behaviour - I repaired the working device, and now also doesn't report power

[davet2001]

Not sure why, but restoring the database file does not seem to restore behaviour, even if i powercycle and reset the usb stick. My original 'working' device doesn't seem to be able to report any power now. Please advise if there's anything I can do to help resolve this. Definitely seems to be a zigbee2mqtt issue rather than an SP600 issue.

[davet2001]

Spent some time trying to narrow down when this problem started. I can confirm that commit eb69ea6 on 9 sep 2019 is working fine.

Shortly after that on the same date we have
d83085e <-- fails to launch
053e646 <-- fails to launch
411f1fa <-- pairs ok but does not report power (always 0).

Unfortunately d83085e is a massive commit with 57 changed files, 6,322 additions and 13,423 deletions.

I expect one of these changes is what broke the SP600 pairing routine.

[sjorge]

What are the firmwares on those devices, is the working one newer?

[davet2001]

They have slightly different firmware versions - as you can see from the post at the top. But I don’t think that is the main problem any more. Both work if I go back and re-pair with eb69ea6.

Neither work if I use a version later than that.

[davet2001]

Ok narrowed down to a single commit now, but no idea why this is breaking it. Slight correction on the commits, it broke a bit earlier in the history than I thought.

Heres how to turn the problem on and off:

1. git checkout *.json; git checkout eb69ea6808b277232be06f3892fb2cbdeb5b917c; npm install
2. unplug and replug the cc2531, then press the reset button
3. rm data/database.db; npm start
4. hold down the SP600 button for 10sec to start pairing.

Result: database.db contains the 'long' form cluster info for the SP600 device. Console shows power level regularly updating.

1. git checkout *.json; git checkout e26ad2aca2eeb0aa366982481eb921ee603fb6d1; npm install
2. unplug and replug the cc2531, then press the reset button
3. rm data/database.db; npm start
4. hold down the SP600 button for 10sec to start pairing.

Result: database.db contains the 'short' form cluster info for the SP600 device. Console shows power level either zero or constantly at one value.

I've tried this multiple times. Always behaves the same way.

Now looking at the diff. The only thing that has changed is the version from 1.5.1 to 1.6.0:

git diff eb69ea6808b277232be06f3892fb2cb e26ad2aca2eeb0aa366982481eb921ee603fb6d1
warning: refname 'e26ad2aca2eeb0aa366982481eb921ee603fb6d1' is ambiguous.
Git normally never creates a ref that ends with 40 hex characters
because it will be ignored when you just specify 40-hex. These refs
may be created by mistake. For example,

  git checkout -b $br $(git rev-parse ...)

where "$br" is somehow empty and a 40-hex ref is created. Please
examine these refs and maybe delete them. Turn this message off by
running "git config advice.objectNameWarning false"
diff --git a/npm-shrinkwrap.json b/npm-shrinkwrap.json
index a2df9a8..9af6393 100644
--- a/npm-shrinkwrap.json
+++ b/npm-shrinkwrap.json
@@ -1,6 +1,6 @@
 {
   "name": "zigbee2mqtt",
-  "version": "1.5.1",
+  "version": "1.6.0",
   "lockfileVersion": 1,
   "requires": true,
   "dependencies": {
diff --git a/package.json b/package.json
index 46cfb13..4d9e5d5 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "zigbee2mqtt",
-  "version": "1.5.1",
+  "version": "1.6.0",
   "description": "Zigbee to MQTT bridge using zigbee-shepherd",
   "main": "index.js",
   "repository": {

If I manually modify the version to 1.5.1 in the above files, it still doesn't work. But if I do a git checkout it works.

Something must be happening that I don't understand. I'm not really an expert on node.js or git, so that could be why. I can't see how the a checkout of eb69ea6 can behave any differently to a checkout of e26ad2a that has been modified to match eb69ea6.

I'm stumped now for how to fix this, but all of my devices definitely work if I use an old version of zigbee2mqtt.

[davet2001]

Attached log of debug output during pairing for working and not working.
zigbee2mqtt_2352_pairing_debugoutput_working_eb69ea6.txt
zigbee2mqtt_2352_pairing_debugoutput_notworking_da4d26.txt

It looks like in the working case, even after the 'Successfully configured ' debug output, there are several more incoming readRsp messages, and these relate to the missing items (e.g. 'msTemperatureMeasurement') that only appear in database.db in the working configuration. Somehow it looks like there is a bit more configuration going on after the 'succesfully configured'.

In the non working case, there are no more incoming messages displayed after the 'successfully configured' message, until I turned the power on/off a couple of times a few seconds later.

Does that give anyone any ideas what might be wrong?

[davet2001]

Looks like I’ve got a solution now by updating zigbee-herdsman-converters.

Koenkk/zigbee-herdsman-converters#849

[Koenkk]

@davet2001 yes, it is available in the dev branch now, I assume this can be closed.