Zigbee2mqtt: Interview failed while pairing Visonic MCT-340 E, but it still (mostly) works

[airdrummingfool]

I'm working on battery and temperature support for the Visonic MCT-340. When I try to pair them (using a modified dev from a couple days ago), the pairing process seems to get pretty far, but - according to zigbee2mqtt - ultimately fails. However, the device sends messages that are received and processed successfully by zigbee2mqtt. The only thing that doesn't seem to work is the configuration process - which means I can't get temperature reporting working.

It's worth mentioning that the pairing process also fails without my modifications.

Here's the debug log output of a pairing attempt. Note that I've tried this quite a few times, with the same result each time. If I try to push the button, toggle the sensor, etc while pairing is happening, the device sends another pairing announcement.

zigbee2mqtt:debug 2019-10-17T05:08:21: Received MQTT message on 'zigbee2mqtt/bridge/config/permit_join' with data 'true'
zigbee2mqtt:info  2019-10-17T05:08:21: Zigbee: allowing new devices to join.
zigbee2mqtt:info  2019-10-17T05:08:21: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.6.0","commit":"4abafa9","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}},"log_level":"debug","permit_join":true}'
zigbee2mqtt:info  2019-10-17T05:08:29: Device '0x000d6f000b1231b0' joined
zigbee2mqtt:info  2019-10-17T05:08:29: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"device_connected","message":{"friendly_name":"0x000d6f000b1231b0"}}'
zigbee2mqtt:info  2019-10-17T05:08:29: Starting interview of '0x000d6f000b1231b0'
zigbee2mqtt:info  2019-10-17T05:08:29: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_started","meta":{"friendly_name":"0x000d6f000b1231b0"}}'
zigbee2mqtt:debug 2019-10-17T05:08:30: Device '0x000d6f000b1231b0' announced itself
zigbee2mqtt:debug 2019-10-17T05:08:41: Received Zigbee message from '0x000d6f000b1231b0', type 'readResponse', cluster 'genBasic', data '{"modelId":"MCT-340 E","manufacturerName":"Visonic","powerSource":3}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2019-10-17T05:08:42: Received Zigbee message from '0x000d6f000b1231b0', type 'readResponse', cluster 'genBasic', data '{"zclVersion":1,"appVersion":1,"stackVersion":0}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2019-10-17T05:08:42: Received Zigbee message from '0x000d6f000b1231b0', type 'readResponse', cluster 'genBasic', data '{"hwVersion":1}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2019-10-17T05:08:47: Received Zigbee message from '0x000d6f000b1231b0', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"zonestatus":37,"extendedstatus":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-17T05:08:47: MQTT publish: topic 'zigbee2mqtt/0x000d6f000b1231b0', payload '{"contact":false,"tamper":true,"battery_low":false,"linkquality":60}'
zigbee2mqtt:error 2019-10-17T05:09:01: Failed to interview '0x000d6f000b1231b0', device has not successfully been paired
zigbee2mqtt:info  2019-10-17T05:09:01: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_failed","meta":{"friendly_name":"0x000d6f000b1231b0"}}'
zigbee2mqtt:debug 2019-10-17T05:09:18: Received Zigbee message from '0x000d6f000b1231b0', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"zonestatus":36,"extendedstatus":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-17T05:09:18: MQTT publish: topic 'zigbee2mqtt/0x000d6f000b1231b0', payload '{"contact":true,"tamper":true,"battery_low":false,"linkquality":55}'

The device does get added to database.db - here's the excerpt:

{
    "id": 6,
    "type": "EndDevice",
    "ieeeAddr": "0x000d6f000b1231b0",
    "nwkAddr": 53574,
    "manufId": 4113,
    "manufName": "Visonic",
    "powerSource": "Battery",
    "modelId": "MCT-340 E",
    "epList": [1],
    "endpoints": {
        "1": {
            "profId": 260,
            "epId": 1,
            "devId": 1026,
            "inClusterList": [0, 1, 3, 1026, 1280, 32, 2821],
            "outClusterList": [25],
            "clusters": {
                "genBasic": {
                    "attributes": {
                        "modelId": "MCT-340 E",
                        "manufacturerName": "Visonic",
                        "powerSource": 3,
                        "zclVersion": 1,
                        "appVersion": 1,
                        "stackVersion": 0,
                        "hwVersion": 1
                    }
                }
            },
            "binds": []
        }
    },
    "appVersion": 1,
    "stackVersion": 0,
    "hwVersion": 1,
    "zclVersion": 1,
    "interviewCompleted": false,
    "meta": {}
}

my takeaway from this is that interviewCompleted is false, and meta is empty (should be configureKey: 1), which proves that configuration is not happening.

My configure code is pretty straightforward:

    {
        zigbeeModel: ['MCT-340 E'],
        model: 'MCT-340 E',
        vendor: 'Visonic',
        description: 'Magnetic door & window contact sensor',
        supports: 'contact, temperature',
        fromZigbee: [fz.iaszone_contact, fz.temperature, fz.battery_3V_2100],
        toZigbee: [],
        meta: {configureKey: 1},
        configure: async (device, coordinatorEndpoint) => {
            const endpoint = device.getEndpoint(1);
            await bind(endpoint, coordinatorEndpoint, ['msTemperatureMeasurement']);
            await configureReporting.temperature(endpoint);
            await configureReporting.batteryPercentageRemaining(endpoint);
        },
    },

Again, the device seems to function fine (and even reports battery voltage somehow, even though it's - ostensibly - not getting subscribed to), despite the failure to pair message. The important thing that isn't happening is the device configuration, which means I cannot subscribe to temperature reporting.

[airdrummingfool]

I believe that zigbee2mqtt's error message may be incorrect - that is, pairing _does_ complete successfully. I have been able to force configuration (and get a temperature reading) by doing the following:

1. Stop zigbee2mqtt
2. Edit data/database.db to set interviewCompleted to true, and meta to {"configured": 0}
3. Start zigbee2mqtt
4. Wait for a log message indicating z2m is attempting to configure the device, and then toggle the sensor (this causes the device to communicate with z2m and enables it to be configured).

zigbee2mqtt:info  2019-10-17T06:14:48: Configuring '0x000d6f000b1231b0'
zigbee2mqtt:info  2019-10-17T06:14:50: Succesfully configured '0x000d6f000b1231b0'

After this, I start to receive periodic temperature reports.

[Koenkk]

I think we should also configure devices even if interview failed.

Changing https://github.com/Koenkk/zigbee2mqtt/blob/dev/lib/extension/deviceConfigure.js#L27 to if (device.interviewing === true) { should fix it.

Feel free to make a pr if this works.

[airdrummingfool]

That seems to have done the trick! I'll send a PR shortly. Thank you!

Here's a log for posterity - it failed to pair the first time, but retried without any intervention on my part:

zigbee2mqtt:debug 2019-10-17T08:11:59: Received MQTT message on 'zigbee2mqtt/bridge/config/permit_join' with data 'true'
zigbee2mqtt:info  2019-10-17T08:11:59: Zigbee: allowing new devices to join.
zigbee2mqtt:info  2019-10-17T08:11:59: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.6.0","commit":"4abafa9","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}},"log_level":"debug","permit_join":true}'
zigbee2mqtt:info  2019-10-17T08:12:07: Device '0x000d6f000b1b748f' joined
zigbee2mqtt:info  2019-10-17T08:12:07: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"device_connected","message":{"friendly_name":"0x000d6f000b1b748f"}}'
zigbee2mqtt:info  2019-10-17T08:12:07: Starting interview of '0x000d6f000b1b748f'
zigbee2mqtt:info  2019-10-17T08:12:07: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_started","meta":{"friendly_name":"0x000d6f000b1b748f"}}'
zigbee2mqtt:debug 2019-10-17T08:12:07: Device '0x000d6f000b1b748f' announced itself
zigbee2mqtt:debug 2019-10-17T08:12:19: Device '0x000d6f000b1b748f' announced itself
zigbee2mqtt:error 2019-10-17T08:12:27: Failed to interview '0x000d6f000b1b748f', device has not successfully been paired
zigbee2mqtt:info  2019-10-17T08:12:27: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_failed","meta":{"friendly_name":"0x000d6f000b1b748f"}}'
zigbee2mqtt:info  2019-10-17T08:12:55: Starting interview of '0x000d6f000b1b748f'
zigbee2mqtt:info  2019-10-17T08:12:55: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_started","meta":{"friendly_name":"0x000d6f000b1b748f"}}'
zigbee2mqtt:debug 2019-10-17T08:12:55: Device '0x000d6f000b1b748f' announced itself
zigbee2mqtt:debug 2019-10-17T08:13:02: Device '0x000d6f000b1b748f' announced itself
zigbee2mqtt:debug 2019-10-17T08:13:07: Received Zigbee message from '0x000d6f000b1b748f', type 'readResponse', cluster 'genBasic', data '{"modelId":"MCT-340 E","manufacturerName":"Visonic","powerSource":3}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-17T08:13:07: MQTT publish: topic 'homeassistant/binary_sensor/0x000d6f000b1b748f/contact/config', payload '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","state_topic":"zigbee2mqtt/0x000d6f000b1b748f","json_attributes_topic":"zigbee2mqtt/0x000d6f000b1b748f","name":"0x000d6f000b1b748f_contact","unique_id":"0x000d6f000b1b748f_contact_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f000b1b748f"],"name":"0x000d6f000b1b748f","sw_version":"Zigbee2mqtt 1.6.0","model":"Magnetic door & window contact sensor (MCT-340 E)","manufacturer":"Visonic"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:info  2019-10-17T08:13:07: MQTT publish: topic 'homeassistant/sensor/0x000d6f000b1b748f/temperature/config', payload '{"unit_of_measurement":"°C","device_class":"temperature","value_template":"{{ value_json.temperature }}","state_topic":"zigbee2mqtt/0x000d6f000b1b748f","json_attributes_topic":"zigbee2mqtt/0x000d6f000b1b748f","name":"0x000d6f000b1b748f_temperature","unique_id":"0x000d6f000b1b748f_temperature_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f000b1b748f"],"name":"0x000d6f000b1b748f","sw_version":"Zigbee2mqtt 1.6.0","model":"Magnetic door & window contact sensor (MCT-340 E)","manufacturer":"Visonic"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:info  2019-10-17T08:13:07: MQTT publish: topic 'homeassistant/sensor/0x000d6f000b1b748f/battery/config', payload '{"unit_of_measurement":"%","device_class":"battery","value_template":"{{ value_json.battery }}","state_topic":"zigbee2mqtt/0x000d6f000b1b748f","json_attributes_topic":"zigbee2mqtt/0x000d6f000b1b748f","name":"0x000d6f000b1b748f_battery","unique_id":"0x000d6f000b1b748f_battery_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f000b1b748f"],"name":"0x000d6f000b1b748f","sw_version":"Zigbee2mqtt 1.6.0","model":"Magnetic door & window contact sensor (MCT-340 E)","manufacturer":"Visonic"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:info  2019-10-17T08:13:07: MQTT publish: topic 'homeassistant/sensor/0x000d6f000b1b748f/linkquality/config', payload '{"unit_of_measurement":"-","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/0x000d6f000b1b748f","json_attributes_topic":"zigbee2mqtt/0x000d6f000b1b748f","name":"0x000d6f000b1b748f_linkquality","unique_id":"0x000d6f000b1b748f_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f000b1b748f"],"name":"0x000d6f000b1b748f","sw_version":"Zigbee2mqtt 1.6.0","model":"Magnetic door & window contact sensor (MCT-340 E)","manufacturer":"Visonic"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:debug 2019-10-17T08:13:07: Received Zigbee message from '0x000d6f000b1b748f', type 'readResponse', cluster 'genBasic', data '{"zclVersion":1,"appVersion":1,"stackVersion":0}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2019-10-17T08:13:08: Received Zigbee message from '0x000d6f000b1b748f', type 'readResponse', cluster 'genBasic', data '{"hwVersion":1}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2019-10-17T08:13:12: Received Zigbee message from '0x000d6f000b1b748f', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"zonestatus":37,"extendedstatus":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-17T08:13:12: MQTT publish: topic 'zigbee2mqtt/0x000d6f000b1b748f', payload '{"contact":false,"tamper":true,"battery_low":false,"linkquality":57,"last_seen":"2019-10-17T08:13:12.660Z"}'
zigbee2mqtt:error 2019-10-17T08:13:26: Failed to interview '0x000d6f000b1b748f', device has not successfully been paired
zigbee2mqtt:info  2019-10-17T08:13:26: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_failed","meta":{"friendly_name":"0x000d6f000b1b748f"}}'
zigbee2mqtt:info  2019-10-17T08:13:26: Configuring '0x000d6f000b1b748f'
zigbee2mqtt:info  2019-10-17T08:13:28: Succesfully configured '0x000d6f000b1b748f'

[wixoff]

Very, very timely! I spent some time yesterday unsuccessfully trying to pair one of these sensors, and I received an "interview failed" each time. I will try again with latest-dev and report back.

I have managed to pair these in the past, but I don't know what combination of settings and moon phases it took, because failures have been far more frequent than successes.

[airdrummingfool]

@wixoff the changes so far don’t fix the “interview failed” message, they just allow the device to be configured even if it does fail. In my experience, the pairing process is often (but not always) successful even when the interview process reports failure.

FYI I’m also working on improving feature support for these sensors - adding temperature and battery level reporting. I plan to submit PRs within the next few days.

[wixoff]

@airdrummingfool Awesome. Not only have my past attempts resulted in a failed interview, but the devices themselves always remain in pairing mode (three blinks, repeated). So we'll see how this works.

[airdrummingfool]

@wixoff Ah. Fair warning, I don't believe the above change affects pairing at all... but we shall see!

[wixoff]

@airdrummingfool It works! I have only had time to add back one of four so far, and it is still showing as "interview failed," but it is connected, configured, and reporting. Nice work!

I don't see any reason to hold this issue open any longer.

[airdrummingfool]

@wixoff huh, glad to hear it!

It's worth noting that the interview still fails, but since the underlying issue (the device not being configured if the interview fails) has been resolved, I'll go ahead and close this.

[SkyHyperV]

I get error when I tried to edit the database file as you suggested:

Nov 11 21:04:23 snips_master npm[2433]: #033[31mzigbee2mqtt:error#033[39m 2019-11-12T03:04:23: Failed to call 'DeviceConfigure' 'onZigbeeEvent' (TypeError: Cannot read property 'meta' of undefined
Nov 11 21:04:23 snips_master npm[2433]: at DeviceConfigure.shouldConfigure (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:19:97)
Nov 11 21:04:23 snips_master npm[2433]: at DeviceConfigure.onZigbeeEvent (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:48:18)
Nov 11 21:04:23 snips_master npm[2433]: at Controller.callExtensionMethod (/opt/zigbee2mqtt/lib/controller.js:320:44))

[airdrummingfool]

@SkyHyperV This issue was fixed in 1.7.0. I'd recommend updating and then re-pairing any MCT-340 devices you have.

The error you're seeing looks like what happens with there are configuration instructions, but the device doesn't have a configured value in the meta object in the database (such as when an update adds configure commands to a device you paired with a prior version that didn't have any configure commands). You should be able to fix this by setting the device's meta value to {"configured": 0} in data/database.db.

[SkyHyperV]

I just got my controller yesterday and set this up so its on 1.7.0 and still getting the error on a Iris Motion sensor. See below details regarding version, error and how my DB looks when I start the service:

VERSION:
Nov 12 08:53:42 snips_master npm[7591]: > [email protected] start /opt/zigbee2mqtt

DATA -- notice I put interviewCompleted to true and meta to "configured": 0 within the array { }
{"id":2,"type":"EndDevice","ieeeAddr":"0xd0cf5efffec8ef5d","nwkAddr":3583,"manufId":4667,"manufName":"iMagic by GreatStar","powerSource":"Unknown","modelId":"1117-S","epList":[1],"endpoints":{"1":{"profId":260,"epId":1,"devId":1026,"inClusterList":[0,1,3,32,1026,1029,1280,2821,64513,64514],"outClusterList":[3,25],"clusters":{"genBasic":{"attributes":{"modelId":"1117-S","manufacturerName":"iMagic by GreatStar","powerSource":0,"zclVersion":2,"appVersion":0,"stackVersion":0,"hwVersion":0}}},"binds":[]}},"appVersion":0,"stackVersion":0,"hwVersion":0,"zclVersion":2,"interviewCompleted":true,"meta":{"configured":0}}

ERROR:
Nov 12 08:48:56 snips_master npm[2698]: #033[33mzigbee2mqtt:warn #033[39m 2019-11-12T14:48:56: Received message from unsupported device with Zigbee model '1117-S'
Nov 12 08:48:56 snips_master npm[2698]: #033[33mzigbee2mqtt:warn #033[39m 2019-11-12T14:48:56: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
Nov 12 08:48:56 snips_master npm[2698]: #033[31mzigbee2mqtt:error#033[39m 2019-11-12T14:48:56: Failed to call 'DeviceConfigure' 'onZigbeeEvent' (TypeError: Cannot read property 'meta' of undefined
Nov 12 08:48:56 snips_master npm[2698]: at DeviceConfigure.shouldConfigure (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:19:97)
Nov 12 08:48:56 snips_master npm[2698]: at DeviceConfigure.onZigbeeEvent (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:48:18)
Nov 12 08:48:56 snips_master npm[2698]: at Controller.callExtensionMethod (/opt/zigbee2mqtt/lib/controller.js:320:44))
Nov 12 08:49:27 snips_master npm[2698]: #033[33mzigbee2mqtt:warn #033[39m 2019-11-12T14:49:27: Received message from unsupported device with Zigbee model '1117-S'
Nov 12 08:49:27 snips_master npm[2698]: #033[33mzigbee2mqtt:warn #033[39m 2019-11-12T14:49:27: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
Nov 12 08:49:27 snips_master npm[2698]: #033[31mzigbee2mqtt:error#033[39m 2019-11-12T14:49:27: Failed to call 'DeviceConfigure' 'onZigbeeEvent' (TypeError: Cannot read property 'meta' of undefined
Nov 12 08:49:27 snips_master npm[2698]: at DeviceConfigure.shouldConfigure (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:19:97)
Nov 12 08:49:27 snips_master npm[2698]: at DeviceConfigure.onZigbeeEvent (/opt/zigbee2mqtt/lib/extension/deviceConfigure.js:48:18)
Nov 12 08:49:27 snips_master npm[2698]: at Controller.callExtensionMethod (/opt/zigbee2mqtt/lib/controller.js:320:44))

[airdrummingfool]

@SkyHyperV Your device, model 1117-S by "iMagic by GreatStar", is not yet supported by Zigbee2mqtt. You should follow the instructions at https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html, and open a separate Github issue if you need support.

[bohtho]

@airdrummingfool @Koenkk Should this be the same in zigbee-herdsman 0.12.17 (node-red-contrib-zigbee) with zStack3x0 20191106? Meaning I stop it, edit database file with "interviewCompleted":true, and meta to {"configured": 0}, and restart it but it doesn't seem to finish interviewing. The device is basically working but it doesn't report anything and the database file is back to "interviewCompleted":false.

Is there another trick ? I should say in my case the exact device is a Hue Lightstrip LST002, but the problem seems very similar. I have also tried repairing without any greater success.

[bohtho]

I managed to get it to a completed interviewed state after doing the procedure above (which didn’t seem to make a difference actually), repairing 3 times, soft resetting, factory resetting, and repairing the light strip again.

Now there are more clusters like basic, onoff and level. But still none for color....? Seems just partially configured then?