search

WebThingsIO / zigbee-adapter

Zigbee adapter add-on for WebThings Gateway
Mozilla Public License 2.0
46 stars 29 forks source link

Pairing Problems #113

Open lgretton opened 5 years ago

lgretton commented 5 years ago

I'm using a Digi-Key Xstick. I've managed to get a single Osram lightbulb paired in the past, but after a reinstall when trying to pair some other devices unsuccessfully (a Xiaomi motion sensor and Ikea bulb) I now can't get anything to pair, at least not as far as the UI is concerned.

From the debugging output it seems that maybe the code just isn't communicating with the UI. Below is what happens when the gateway is started, followed by a reset of the bulb while trying to pair again. Any idea what's wrong? I've tried resetting everything and deleting the zb-.json file, all to no avail. The json file even shows my Ikea bulb, though I've never successfully paired it.

2019-03-27 08:08:03.449 INFO   : HTTP server listening on port 8080
2019-03-27 08:08:03.493 INFO   : DNS config is: pi3-01
2019-03-27 08:08:03.496 INFO   : Service Discovery: changing profile - local domain is now: pi3-01
2019-03-27 08:08:04.903 INFO   : Service Discovery: state changed to: true
2019-03-27 08:08:06.040 INFO   : Loading add-on: zigbee-adapter
2019-03-27 08:08:06.777 INFO   : zigbee: Opening database: /home/liam/.mozilla-iot/config/db.sqlite3
2019-03-27 08:08:06.819 INFO   : zigbee: Loading add-on for zigbee-adapter from /home/liam/.mozilla-iot/addons/zigbee-adapter
2019-03-27 08:08:07.448 INFO   : zigbee: DEBUG config = 'frames'
2019-03-27 08:08:07.451 INFO   : zigbee: Enabling DEBUG_frames
2019-03-27 08:08:08.171 INFO   : zigbee: this.driver = XBeeDriver {}
2019-03-27 08:08:08.173 INFO   : zigbee: XBeeDriver: Using serial port /dev/ttyUSB0
2019-03-27 08:08:08.179 INFO   : zigbee: Sent: AT Command (0x08) Get API Mode
2019-03-27 08:08:08.213 INFO   : zigbee: Rcvd: AT Command Response (0x88) API Mode
2019-03-27 08:08:08.216 INFO   : zigbee: API Mode already set to 1 (i.e. no need to change)
2019-03-27 08:08:08.218 INFO   : zigbee: Sent: AT Command (0x08) Get Device Type Identifier (DD)
2019-03-27 08:08:08.242 INFO   : zigbee: Rcvd: AT Command Response (0x88) Device Type Identifier (DD)
2019-03-27 08:08:08.245 INFO   : zigbee: Sent: AT Command (0x08) Get Configured 64-bit PAN ID (ID)
2019-03-27 08:08:08.273 INFO   : zigbee: Rcvd: AT Command Response (0x88) Configured 64-bit PAN ID (ID)
2019-03-27 08:08:08.276 INFO   : zigbee: Sent: AT Command (0x08) Get Serial Number High (SH)
2019-03-27 08:08:08.305 INFO   : zigbee: Rcvd: AT Command Response (0x88) Serial Number High (SH)
2019-03-27 08:08:08.307 INFO   : zigbee: Sent: AT Command (0x08) Get Serial Number Low (SL)
2019-03-27 08:08:08.337 INFO   : zigbee: Rcvd: AT Command Response (0x88) Serial Number Low (SL)
2019-03-27 08:08:08.340 INFO   : zigbee: Sent: AT Command (0x08) Get 16-bit Network Address (MY)
2019-03-27 08:08:08.369 INFO   : zigbee: Rcvd: AT Command Response (0x88) 16-bit Network Address (MY)
2019-03-27 08:08:08.371 INFO   : zigbee: Sent: AT Command (0x08) Get Operating 64-bit PAN ID (OP)
2019-03-27 08:08:08.401 INFO   : zigbee: Rcvd: AT Command Response (0x88) Operating 64-bit PAN ID (OP)
2019-03-27 08:08:08.403 INFO   : zigbee: Sent: AT Command (0x08) Get Operating 16-bit PAN ID (OI)
2019-03-27 08:08:08.433 INFO   : zigbee: Rcvd: AT Command Response (0x88) Operating 16-bit PAN ID (OI)
2019-03-27 08:08:08.435 INFO   : zigbee: Sent: AT Command (0x08) Get Operating Channel (CH)
2019-03-27 08:08:08.465 INFO   : zigbee: Rcvd: AT Command Response (0x88) Operating Channel (CH)
2019-03-27 08:08:08.467 INFO   : zigbee: Sent: AT Command (0x08) Get Scan Channels (SC)
2019-03-27 08:08:08.497 INFO   : zigbee: Rcvd: AT Command Response (0x88) Scan Channels (SC)
2019-03-27 08:08:08.500 INFO   : zigbee: Sent: AT Command (0x08) Get Node Identifier (NI)
2019-03-27 08:08:08.529 INFO   : zigbee: Rcvd: AT Command Response (0x88) Node Identifier (NI)
2019-03-27 08:08:08.531 INFO   : zigbee: Sent: AT Command (0x08) Get Num Remaining Children (NC)
2019-03-27 08:08:08.560 INFO   : zigbee: Rcvd: AT Command Response (0x88) Num Remaining Children (NC)
2019-03-27 08:08:08.563 INFO   : zigbee: Sent: AT Command (0x08) Get Zigbee Stack Profile (ZS)
2019-03-27 08:08:08.593 INFO   : zigbee: Rcvd: AT Command Response (0x88) Zigbee Stack Profile (ZS)
2019-03-27 08:08:08.595 INFO   : zigbee: Sent: AT Command (0x08) Get API Options (AO)
2019-03-27 08:08:08.625 INFO   : zigbee: Rcvd: AT Command Response (0x88) API Options (AO)
2019-03-27 08:08:08.627 INFO   : zigbee: Sent: AT Command (0x08) Get Encyption Enabled (EE)
2019-03-27 08:08:08.657 INFO   : zigbee: Rcvd: AT Command Response (0x88) Encyption Enabled (EE)
2019-03-27 08:08:08.660 INFO   : zigbee: Sent: AT Command (0x08) Get Encryption Options (EO)
2019-03-27 08:08:08.689 INFO   : zigbee: Rcvd: AT Command Response (0x88) Encryption Options (EO)
2019-03-27 08:08:08.691 INFO   : zigbee: No configuration required
2019-03-27 08:08:08.697 INFO   : zigbee: Sent: AT Command (0x08) Set Node Join Time (NJ)
2019-03-27 08:08:08.721 INFO   : zigbee: Rcvd: AT Command Response (0x88) Node Join Time (NJ)
2019-03-27 08:08:08.723 INFO   : zigbee: Sent: Explicit Tx 0013a200415872b1 ZDO 0036 Mgmt Permit Join Req (0x0036) permitDuration: 0
2019-03-27 08:08:08.726 INFO   : zigbee: Sent:   Duration:0
2019-03-27 08:08:08.803 INFO   : zigbee: Rcvd: Explicit Rx 0013a200415872b1 ZDO 8036 Mgmt Permit Join Resp (0x8036)  status: success (0)
2019-03-27 08:08:08.806 INFO   : zigbee: Rcvd:   Status:0
2019-03-27 08:08:08.808 INFO   : zigbee:        Device Type: 0x3000c - XStick
2019-03-27 08:08:08.809 INFO   : zigbee:    Network Address: 0013a200415872b1 0000
2019-03-27 08:08:08.811 INFO   : zigbee:    Node Identifier:
2019-03-27 08:08:08.813 INFO   : zigbee:  Configured PAN Id: c2818437f5b176b4
2019-03-27 08:08:08.815 INFO   : zigbee:   Operating PAN Id: c2818437f5b176b4 5f17
2019-03-27 08:08:08.817 INFO   : zigbee:  Operating Channel: 23
2019-03-27 08:08:08.819 INFO   : zigbee:  Channel Scan Mask: 1ffe
2019-03-27 08:08:08.820 INFO   : zigbee:          Join Time: undefined
2019-03-27 08:08:08.822 INFO   : zigbee: Remaining Children: 10
2019-03-27 08:08:08.823 INFO   : zigbee:      Stack Profile: 2
2019-03-27 08:08:08.824 INFO   : zigbee:        API Options: 3
2019-03-27 08:08:08.825 INFO   : zigbee: Encryption Enabled: 1
2019-03-27 08:08:08.826 INFO   : zigbee: Encryption Options: 2
2019-03-27 08:08:08.828 INFO   : zigbee: ZigbeeNode created: addr64: 0013a200415872b1 addr16: 0000
2019-03-27 08:08:08.831 INFO   : zigbee: readDeviceInfo: read failed: { Error: ENOENT: no such file or directory, open '/home/liam/.mozilla-iot/config/zb-0013a200415872b1.json'
2019-03-27 08:08:08.832 INFO   : zigbee:   errno: -2,
2019-03-27 08:08:08.833 INFO   : zigbee:   code: 'ENOENT',
2019-03-27 08:08:08.834 INFO   : zigbee:   syscall: 'open',
2019-03-27 08:08:08.835 INFO   : zigbee:   path: '/home/liam/.mozilla-iot/config/zb-0013a200415872b1.json' }
2019-03-27 08:08:08.836 INFO   : zigbee: Sent: Explicit Tx 0013a200415872b1 ZDO 0031 Mgmt LQI (Neighbor Table) Req (0x0031)
2019-03-27 08:08:08.837 INFO   : zigbee: Sent:   si:0
2019-03-27 08:08:08.951 INFO   : zigbee: Rcvd: Explicit Rx 0013a200415872b1 ZDO 8031 Mgmt LQI (Neighbor Table) Resp (0x8031)  status: success (0)
2019-03-27 08:08:08.955 INFO   : zigbee: Rcvd:   Status:0 si:0
2019-03-27 08:08:08.957 INFO   : zigbee: Rcvd:   PAN:c2818437f5b176b4 Addr:000b57fffec9ff00 8204 DT:Router R:None     PJ:? D:15 LQI:254
2019-03-27 08:08:08.960 INFO   : zigbee: Rcvd:   PAN:c2818437f5b176b4 Addr:8418260000cbbafc e01d DT:Router R:None     PJ:? D:15 LQI:255
2019-03-27 08:08:08.964 INFO   : zigbee: ZigbeeNode created: addr64: 000b57fffec9ff00 addr16: 8204
2019-03-27 08:08:08.967 INFO   : zigbee: ZigbeeNode created: addr64: 8418260000cbbafc addr16: e01d
2019-03-27 08:08:08.970 INFO   : zigbee: ----- Scan Starting -----
2019-03-27 08:08:08.974 INFO   : zigbee: ----- Nodes -----
2019-03-27 08:08:08.976 INFO   : zigbee: Node: 0013a200415872b1 0000 Name: zb-0013a200415872b1-Dongle       rebindRequired: true endpoints: []
2019-03-27 08:08:08.979 INFO   : zigbee:   Neighbor: 000b57fffec9ff00 8204 DT: Router R: None     PJ: ? D:  15 LQI: 254
2019-03-27 08:08:08.982 INFO   : zigbee:   Neighbor: 8418260000cbbafc e01d DT: Router R: None     PJ: ? D:  15 LQI: 255
2019-03-27 08:08:08.984 INFO   : zigbee: Node: 000b57fffec9ff00 8204 Name:                                  rebindRequired: true endpoints: []
2019-03-27 08:08:08.987 INFO   : zigbee: Node: 8418260000cbbafc e01d Name:                                  rebindRequired: true endpoints: []
2019-03-27 08:08:08.989 INFO   : zigbee: -----------------
2019-03-27 08:08:08.992 INFO   : zigbee: ----- Scan Complete -----
2019-03-27 08:08:08.996 INFO   : zigbee: Sent: Explicit Tx 000b57fffec9ff00 ZDO 0000 Network Address Req (0x0000)
2019-03-27 08:08:08.999 INFO   : zigbee: Sent:   Addr:000b57fffec9ff00
2019-03-27 08:08:09.992 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZDO 0000 Network Address Req (0x0000)
2019-03-27 08:08:09.995 INFO   : zigbee: Sent:   Addr:8418260000cbbafc
2019-03-27 08:08:10.242 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZDO 8000 Network Address Resp (0x8000)  status: success (0)
2019-03-27 08:08:10.246 INFO   : zigbee: Rcvd:   Addr:8418260000cbbafc e01d si:0 []
2019-03-27 08:08:10.249 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZDO 0005 Active Endpoints Req (0x0005)
2019-03-27 08:08:10.252 INFO   : zigbee: Sent:   Dest: e01d
2019-03-27 08:08:10.370 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZDO 8005 Active Endpoints Resp (0x8005)  status: success (0)
2019-03-27 08:08:10.374 INFO   : zigbee: Rcvd:   Status:0 Addr:e01d EP:[3]
2019-03-27 08:08:10.378 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZDO 0004 Simple Descriptor Req (0x0004)
2019-03-27 08:08:10.381 INFO   : zigbee: Sent:   Addr:e01d:3
2019-03-27 08:08:10.530 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZDO 8004 Simple Descriptor Resp (0x8004)  status: success (0)
2019-03-27 08:08:10.537 INFO   : zigbee: Rcvd:   Status:0 Addr:e01d EP:3 Prof:c05e DevId:0210 DevVer:2
2019-03-27 08:08:10.541 INFO   : zigbee: Rcvd:   In:  1000-lightLink
2019-03-27 08:08:10.543 INFO   : zigbee: Rcvd:   In:  0000-genBasic
2019-03-27 08:08:10.546 INFO   : zigbee: Rcvd:   In:  0003-genIdentify
2019-03-27 08:08:10.549 INFO   : zigbee: Rcvd:   In:  0004-genGroups
2019-03-27 08:08:10.551 INFO   : zigbee: Rcvd:   In:  0005-genScenes
2019-03-27 08:08:10.554 INFO   : zigbee: Rcvd:   In:  0006-genOnOff
2019-03-27 08:08:10.556 INFO   : zigbee: Rcvd:   In:  0008-genLevelCtrl
2019-03-27 08:08:10.559 INFO   : zigbee: Rcvd:   In:  0300-lightingColorCtrl
2019-03-27 08:08:10.562 INFO   : zigbee: Rcvd:   In:  fc04
2019-03-27 08:08:10.564 INFO   : zigbee: Rcvd:   In:  fc0f
2019-03-27 08:08:10.567 INFO   : zigbee: Rcvd:   Out: 0019-genOta
2019-03-27 08:08:10.572 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0000 genBasic read
2019-03-27 08:08:10.574 INFO   : zigbee: Sent:       5:modelId
2019-03-27 08:08:10.576 INFO   : zigbee: Sent:       7:powerSource
2019-03-27 08:08:10.790 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0000 genBasic readRsp
2019-03-27 08:08:10.794 INFO   : zigbee: Rcvd:       5:modelId 0:success 66:charStr Classic A60 RGBW
2019-03-27 08:08:10.797 INFO   : zigbee: Rcvd:       7:powerSource 0:success 48:enum8 0x2a(42)
2019-03-27 08:08:10.809 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0000 genBasic defaultRsp
2019-03-27 08:08:10.812 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:08:10.816 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl read
2019-03-27 08:08:10.820 INFO   : zigbee: Sent:   16394:colorCapabilities
2019-03-27 08:08:10.834 INFO   : zigbee: Sent:       8:colorMode
2019-03-27 08:08:11.069 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0300 lightingColorCtrl readRsp
2019-03-27 08:08:11.072 INFO   : zigbee: Rcvd:   16394:colorCapabilities 0:success 25:bitmap16 0x1f(31)
2019-03-27 08:08:11.074 INFO   : zigbee: Rcvd:       8:colorMode 0:success 48:enum8 0x2(2)
2019-03-27 08:08:11.076 INFO   : zigbee: Stored colorCapabilities: 31
2019-03-27 08:08:11.078 INFO   : zigbee: Stored colorMode: 2
2019-03-27 08:08:11.079 INFO   : zigbee: handleReadRsp: ##### No property found for frame #####
2019-03-27 08:08:11.082 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl defaultRsp
2019-03-27 08:08:11.084 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:08:11.085 INFO   : zigbee: Stored colorCapabilities: 31
2019-03-27 08:08:11.086 INFO   : zigbee: Stored colorMode: 2
2019-03-27 08:08:11.112 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0008 genLevelCtrl read
2019-03-27 08:08:11.114 INFO   : zigbee: Sent:       0:currentLevel
2019-03-27 08:08:11.284 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0008 genLevelCtrl readRsp
2019-03-27 08:08:11.286 INFO   : zigbee: Rcvd:       0:currentLevel 0:success 32:uint8 0xfe(254)
2019-03-27 08:08:11.289 INFO   : zigbee: zb-8418260000cbbafc-onOffColorLight property: _level profileId: 0104 endpoint: 3 clusterId: 0008 readRsp value: 100.0% (254)
2019-03-27 08:08:11.291 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0008 genLevelCtrl defaultRsp
2019-03-27 08:08:11.293 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:08:11.295 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl read
2019-03-27 08:08:11.296 INFO   : zigbee: Sent:       0:currentHue
2019-03-27 08:08:11.298 INFO   : zigbee: Sent:       1:currentSaturation
2019-03-27 08:08:11.483 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0300 lightingColorCtrl readRsp
2019-03-27 08:08:11.485 INFO   : zigbee: Rcvd:       0:currentHue 0:success 32:uint8 0x0(0)
2019-03-27 08:08:11.487 INFO   : zigbee: Rcvd:       1:currentSaturation 0:success 32:uint8 0x0(0)
2019-03-27 08:08:11.493 INFO   : zigbee: parseColorAttr: colorStr: #FFFFFF hue:0 sat:0, level:100
2019-03-27 08:08:11.495 INFO   : zigbee: zb-8418260000cbbafc-onOffColorLight property: color profileId: 0104 endpoint: 3 clusterId: 0300 readRsp value: #FFFFFF
2019-03-27 08:08:11.498 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl defaultRsp
2019-03-27 08:08:11.500 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:08:11.502 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0006 genOnOff read
2019-03-27 08:08:11.503 INFO   : zigbee: Sent:       0:onOff
2019-03-27 08:08:11.669 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0006 genOnOff readRsp
2019-03-27 08:08:11.673 INFO   : zigbee: Rcvd:       0:onOff 0:success 16:boolean 0x1(1)
2019-03-27 08:08:11.675 INFO   : zigbee: zb-8418260000cbbafc-onOffColorLight property: on profileId: 0104 endpoint: 3 clusterId: 0006 readRsp value: on (1)
2019-03-27 08:08:11.680 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0006 genOnOff defaultRsp
2019-03-27 08:08:11.683 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:08:11.685 INFO   : zigbee: ----- Nodes -----
2019-03-27 08:08:11.688 INFO   : zigbee: Node: 0013a200415872b1 0000 Name: zb-0013a200415872b1-Dongle       rebindRequired: true endpoints: []
2019-03-27 08:08:11.692 INFO   : zigbee:   Neighbor: 000b57fffec9ff00 8204 DT: Router R: None     PJ: ? D:  15 LQI: 254
2019-03-27 08:08:11.695 INFO   : zigbee:   Neighbor: 8418260000cbbafc e01d DT: Router R: None     PJ: ? D:  15 LQI: 255
2019-03-27 08:08:11.697 INFO   : zigbee: Node: 000b57fffec9ff00 8204 Name:                                  rebindRequired: true endpoints: []
2019-03-27 08:08:11.699 INFO   : zigbee: Node: 8418260000cbbafc e01d Name: zb-8418260000cbbafc-onOffColorLi rebindRequired: true endpoints: [ '3' ]
2019-03-27 08:08:11.702 INFO   : zigbee: -----------------
2019-03-27 08:08:11.704 INFO   : zigbee: ----- Update Network Addresses Complete -----
2019-03-27 08:08:13.640 INFO   : Checking for add-on updates...
2019-03-27 08:08:13.739 INFO   : zigbee: Rcvd: ZigBee Transmit Status (0x8B) id: 20 Remote16: fffd Retries: 20 Delivery: Address Not Found (0x24) Discovery: No Discovery Overhead (0x00)
2019-03-27 08:08:13.742 INFO   : zigbee: Transmit Status ERROR: Address Not Found (0x24) id: 20
2019-03-27 08:08:13.743 INFO   : zigbee: { type: 139,
2019-03-27 08:08:13.744 INFO   : zigbee:   id: 20,
2019-03-27 08:08:13.746 INFO   : zigbee:   remote16: 'fffd',
2019-03-27 08:08:13.747 INFO   : zigbee:   transmitRetryCount: 20,
2019-03-27 08:08:13.748 INFO   : zigbee:   deliveryStatus: 36,
2019-03-27 08:08:13.750 INFO   : zigbee:   discoveryStatus: 0 }
2019-03-27 08:08:14.057 INFO   : Finished updating add-ons

Bulb reset and pairing attempted:

2019-03-27 08:21:33.837 INFO   : About to call startPairing on ZigbeeAdapter
2019-03-27 08:21:33.862 INFO   : zigbee: Pairing mode started, timeout = 60
2019-03-27 08:21:33.864 INFO   : zigbee: Sent: AT Command (0x08) Set Node Join Time (NJ)
2019-03-27 08:21:33.890 INFO   : zigbee: Rcvd: AT Command Response (0x88) Node Join Time (NJ)
2019-03-27 08:21:33.894 INFO   : zigbee: Sent: Explicit Tx 0013a200415872b1 ZDO 0036 Mgmt Permit Join Req (0x0036) permitDuration: 60
2019-03-27 08:21:33.897 INFO   : zigbee: Sent:   Duration:60
2019-03-27 08:21:33.971 INFO   : zigbee: Rcvd: Explicit Rx 0013a200415872b1 ZDO 8036 Mgmt Permit Join Resp (0x8036)  status: success (0)
2019-03-27 08:21:33.973 INFO   : zigbee: Rcvd:   Status:0
2019-03-27 08:21:38.094 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZDO 0013 End Device Announcement (0x0013)  status: none (undefined)
2019-03-27 08:21:38.098 INFO   : zigbee: Rcvd:   Addr:8418260000cbbafc aeb5 FFD:1 AC:1 rxOnWhenIdle:1
2019-03-27 08:21:38.101 INFO   : zigbee: Cancelling pairing mode
2019-03-27 08:21:38.103 INFO   : zigbee: Sent: AT Command (0x08) Set Node Join Time (NJ)
2019-03-27 08:21:38.105 INFO   : zigbee: updateAddr16: 8418260000cbbafc Updated addr16 from: e01d to: aeb5
2019-03-27 08:21:38.126 INFO   : zigbee: Rcvd: AT Command Response (0x88) Node Join Time (NJ)
2019-03-27 08:21:38.130 INFO   : zigbee: Sent: Explicit Tx 0013a200415872b1 ZDO 0036 Mgmt Permit Join Req (0x0036) permitDuration: 0
2019-03-27 08:21:38.132 INFO   : zigbee: Sent:   Duration:0
2019-03-27 08:21:38.206 INFO   : zigbee: Rcvd: Explicit Rx 0013a200415872b1 ZDO 8036 Mgmt Permit Join Resp (0x8036)  status: success (0)
2019-03-27 08:21:38.210 INFO   : zigbee: Rcvd:   Status:0
2019-03-27 08:21:38.212 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl read
2019-03-27 08:21:38.215 INFO   : zigbee: Sent:       0:currentHue
2019-03-27 08:21:38.220 INFO   : zigbee: Sent:       1:currentSaturation
2019-03-27 08:21:38.366 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0300 lightingColorCtrl readRsp
2019-03-27 08:21:38.370 INFO   : zigbee: Rcvd:       0:currentHue 0:success 32:uint8 0x0(0)
2019-03-27 08:21:38.372 INFO   : zigbee: Rcvd:       1:currentSaturation 0:success 32:uint8 0x0(0)
2019-03-27 08:21:38.377 INFO   : zigbee: parseColorAttr: colorStr: #FFFFFF hue:0 sat:0, level:100
2019-03-27 08:21:38.379 INFO   : zigbee: zb-8418260000cbbafc-onOffColorLight property: color profileId: 0104 endpoint: 3 clusterId: 0300 readRsp value: #FFFFFF
2019-03-27 08:21:38.382 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0300 lightingColorCtrl defaultRsp
2019-03-27 08:21:38.384 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }
2019-03-27 08:21:38.387 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0006 genOnOff read
2019-03-27 08:21:38.394 INFO   : zigbee: Sent:       0:onOff
2019-03-27 08:21:38.549 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZHA 0006 genOnOff readRsp
2019-03-27 08:21:38.553 INFO   : zigbee: Rcvd:       0:onOff 0:success 16:boolean 0x1(1)
2019-03-27 08:21:38.555 INFO   : zigbee: zb-8418260000cbbafc-onOffColorLight property: on profileId: 0104 endpoint: 3 clusterId: 0006 readRsp value: on (1)
2019-03-27 08:21:38.559 INFO   : zigbee: Sent: Explicit Tx 8418260000cbbafc ZHA 0006 genOnOff defaultRsp
2019-03-27 08:21:38.562 INFO   : zigbee: Sent:   payload: { cmdId: 'readRsp', statusCode: 0 }

Here's the zb-0013a200415872b1.json file.

{
  "driver": {
    "deviceType": "0x3000c",
    "deviceTypeStr": "XStick",
    "serialNumber": "0013a200415872b1",
    "nodeIdentifier": "",
    "configuredPanId64": "c2818437f5b176b4",
    "operatingPanId64": "c2818437f5b176b4",
    "operatingPanId16": "5f17",
    "operatingChannel": 23,
    "scanChannels": "0x1ffe",
    "apiOptions": 3
  },
  "nodes": {
    "000b57fffec9ff00": {
      "addr64": "000b57fffec9ff00",
      "addr16": "8204",
      "activeEndpoints": {
        "1": {
          "profileId": "c05e",
          "deviceId": "0100",
          "deviceVersion": 2,
          "inputClusters": [
            "0000",
            "0003",
            "0004",
            "0005",
            "0006",
            "0008",
            "0b05",
            "1000"
          ],
          "outputClusters": [
            "0005",
            "0019",
            "0020",
            "1000"
          ],
          "classifierAttributesPopulated": true
        }
      },
      "properties": {
        "level": {
          "name": "level",
          "value": 100,
          "visible": true,
          "label": "Brightness",
          "type": "number",
          "@type": "BrightnessProperty",
          "unit": "percent",
          "minimum": 0,
          "maximum": 100,
          "profileId": 260,
          "endpoint": 1,
          "clusterId": 8,
          "attr": "currentLevel",
          "attrId": 0,
          "fireAndForget": true,
          "bindNeeded": false,
          "configReportNeeded": false,
          "initialReadNeeded": false,
          "level": 254
        },
        "on": {
          "name": "on",
          "value": true,
          "visible": true,
          "label": "On/Off",
          "type": "boolean",
          "@type": "OnOffProperty",
          "profileId": 260,
          "endpoint": 1,
          "clusterId": 6,
          "attr": "onOff",
          "attrId": 0,
          "fireAndForget": true,
          "bindNeeded": false,
          "configReportNeeded": false,
          "initialReadNeeded": false
        }
      },
      "name": "zb-000b57fffec9ff00-dimmableLight",
      "type": "dimmableLight",
      "@type": [
        "Light",
        "OnOffSwitch"
      ],
      "defaultName": "zb-000b57fffec9ff00-dimmableLight",
      "extendedTimeout": true,
      "activeEndpointsPopulated": true,
      "nodeInfoEndpointsPopulated": true,
      "modelId": "TRADFRI bulb E27 W opal 1000lm",
      "powerSource": 1,
      "rxOnWhenIdle": 1
    },
    "8418260000cbbafc": {
      "addr64": "8418260000cbbafc",
      "addr16": "aeb5",
      "activeEndpoints": {
        "3": {
          "profileId": "c05e",
          "deviceId": "0210",
          "deviceVersion": 2,
          "inputClusters": [
            "1000",
            "0000",
            "0003",
            "0004",
            "0005",
            "0006",
            "0008",
            "0300",
            "fc04",
            "fc0f"
          ],
          "outputClusters": [
            "0019"
          ],
          "classifierAttributesPopulated": true
        }
      },
      "properties": {
        "_level": {
          "name": "_level",
          "value": 100,
          "visible": false,
          "type": "number",
          "unit": "percent",
          "minimum": 0,
          "maximum": 100,
          "profileId": 260,
          "endpoint": 3,
          "clusterId": 8,
          "attr": "currentLevel",
          "attrId": 0,
          "fireAndForget": true,
          "bindNeeded": false,
          "configReportNeeded": false,
          "initialReadNeeded": false,
          "level": 254
        },
        "color": {
          "name": "color",
          "value": "#FFFFFF",
          "visible": true,
          "label": "Color",
          "type": "string",
          "@type": "ColorProperty",
          "profileId": 260,
          "endpoint": 3,
          "clusterId": 768,
          "attr": [
            "currentHue",
            "currentSaturation"
          ],
          "attrId": [
            0,
            1
          ],
          "fireAndForget": true,
          "bindNeeded": false,
          "configReportNeeded": false,
          "initialReadNeeded": false
        },
        "on": {
          "name": "on",
          "value": true,
          "visible": true,
          "label": "On/Off",
          "type": "boolean",
          "@type": "OnOffProperty",
          "profileId": 260,
          "endpoint": 3,
          "clusterId": 6,
          "attr": "onOff",
          "attrId": 0,
          "fireAndForget": true,
          "bindNeeded": false,
          "configReportNeeded": false,
          "initialReadNeeded": false
        }
      },
      "name": "zb-8418260000cbbafc-onOffColorLight",
      "type": "onOffColorLight",
      "@type": [
        "Light",
        "ColorControl",
        "OnOffSwitch"
      ],
      "defaultName": "zb-8418260000cbbafc-onOffColorLight",
      "extendedTimeout": true,
      "activeEndpointsPopulated": true,
      "nodeInfoEndpointsPopulated": true,
      "colorCapabilities": 31,
      "colorMode": 2,
      "modelId": "Classic A60 RGBW",
      "powerSource": 42,
      "rxOnWhenIdle": 1
    }
  }
}
clockbrain commented 5 years ago

Maybe not quite the same issue but have you tried the work around posted here https://github.com/mozilla-iot/zigbee-adapter/issues/106#issuecomment-471153598?

Seems the UI allows the found device to be saved even though pairing hasn't yet completed. Turn on frame level debugging see https://github.com/mozilla-iot/zigbee-adapter/issues/84#issuecomment-454113905, watch the log file and only save once the pairing has actually completed.

lgretton commented 5 years ago

The debug output above is already at frame level (see line 8). During pairing no discovered devices are shown in the UI, it just chugs away and then tells me nothing was found. If it wasn't for the debug output I wouldn't be aware that the dongle has communicated with the device at all.

I've tried deleting the json file, resetting the dongle (by unplugging and replugging), no change.

dhylands commented 5 years ago

I see this message:

2019-03-27 08:21:38.094 INFO   : zigbee: Rcvd: Explicit Rx 8418260000cbbafc ZDO 0013 End Device Announcement (0x0013)  status: none (undefined)

which tells me that the dongle was able to successfully pair with the device. Looking at the json file, it looks like all of the information was collected. So this tells me that the device should either already be shown as a thing, or it should be showing in the list of new devices. The + screen shows devices which the adapter knows about but which aren't already shown as a thing.

Further debugging would be to run some scripts from this repository: https://github.com/mozilla-iot/curl-examples

First run the login.sh script, and then run the get-things.sh script. This will report all of the things that the gateway knows about. We need to check and see if there is a device already there with an href of "/things/zb-8418260000cbbafc"

dhylands commented 5 years ago

Rebooting the gateway might also help, as I think I've seen cases where the gateways notion of the devices and the adapters notion of the devices get out of sync.

dhylands commented 5 years ago

When resetting the dongle *by unplugging and replugging" you also need to disable/re-enable the zigbee adapter as it doesn't detect the insertion of the dongle.

dhylands commented 5 years ago

If none of that is fruitful, then we can enable some more debugging in the zigbee-adapter. In particular, goto Settings->Addons and click Configure for the Zigbee adapter and then add

classifier, flow, node

to the options already there (presumably frames).

lgretton commented 5 years ago

I'd just written a very long reply having followed all your advice, and then by accident discovered the issue.

I've got the gateway running on a Pi which is fronted by another system ProxyPassing to it within an Apache virtual host. There must be something not quite right about my Apache configuration on the proxy because as soon as I try the Pi directly I see the things in the UI. When going through the proxy the things aren't displayed!

Apologies for the confusion and thanks for all your help, I'll work this one out myself.

dhylands commented 5 years ago

Our gateway also relies on websockets, so I'm guessing that there might be an issue if the websockets aren't also being proxied.

lgretton commented 5 years ago

Thanks - I'm mostly there now, just by including the wstunnel proxy mod in Apache. The thing UI at the point of pairing still doesn't appear, and all things are shown as being disconnected when viewing their properties (though I can still operate them). I guess somewhere in the code the addon is connecting directly to itself, being unaware of the address I wish it to use.