> zigbee2mqtt@0.1.8 start /opt/zigbee2mqtt > node index.js zigbee2mqtt:info 26/11/2018, 20:39:02 Logging to directory: '/opt/zigbee2mqtt/data/log/2018-11-26.20-39-01' zigbee2mqtt:debug 26/11/2018, 20:39:03 Using zigbee-shepherd with settings: '{"net":{"panId":6754,"channelList":[26]},"dbPath":"/opt/zigbee2mqtt/data/database.db","sp":{"baudRate":115200,"rtscts":true}}' zigbee2mqtt:debug 26/11/2018, 20:39:03 Can't load state from file /opt/zigbee2mqtt/data/state.json (doesn't exsist) zigbee2mqtt:info 26/11/2018, 20:39:03 Starting zigbee2mqtt version 0.1.8 (commit #97cc56b) zigbee2mqtt:info 26/11/2018, 20:39:03 Starting zigbee-shepherd zigbee-shepherd:init zigbee-shepherd booting... +0ms zigbee-shepherd:request REQ --> SYS:osalNvRead +83ms zigbee-shepherd:request RSP <-- SYS:osalNvRead, status: 0 +112ms zigbee-shepherd:request REQ --> SAPI:readConfiguration +24ms zigbee-shepherd:request RSP <-- SAPI:readConfiguration, status: 0 +15ms zigbee-shepherd:request REQ --> SAPI:readConfiguration +12ms zigbee-shepherd:request RSP <-- SAPI:readConfiguration, status: 0 +9ms zigbee-shepherd:request REQ --> SAPI:readConfiguration +12ms zigbee-shepherd:request RSP <-- SAPI:readConfiguration, status: 0 +27ms zigbee-shepherd:request REQ --> SAPI:readConfiguration +12ms zigbee-shepherd:request RSP <-- SAPI:readConfiguration, status: 0 +25ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +16ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +15ms zigbee-shepherd:init Now the ZNP is a coordinator. +3ms zigbee-shepherd:request REQ --> SYS:version +3ms zigbee-shepherd:request RSP <-- SYS:version +17ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +8ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +14ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +4ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +13ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +3ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +13ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +4ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +14ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +2ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +13ms zigbee-shepherd:request REQ --> SAPI:getDeviceInfo +3ms zigbee-shepherd:request RSP <-- SAPI:getDeviceInfo +13ms zigbee-shepherd:request REQ --> ZDO:nodeDescReq +11ms zigbee-shepherd:msgHdlr IND <-- ZDO:nodeDescRsp +36ms zigbee-shepherd:request REQ --> ZDO:activeEpReq +7ms zigbee-shepherd:msgHdlr IND <-- ZDO:activeEpRsp +49ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +10ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +27ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +3ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +24ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +2ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +24ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +2ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +25ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +2ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +24ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +1ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +25ms zigbee-shepherd:request REQ --> ZDO:nodeDescReq +14ms zigbee-shepherd:msgHdlr IND <-- ZDO:nodeDescRsp +24ms zigbee-shepherd:request REQ --> ZDO:activeEpReq +2ms zigbee-shepherd:msgHdlr IND <-- ZDO:activeEpRsp +24ms zigbee-shepherd:request REQ --> ZDO:mgmtPermitJoinReq +8ms zigbee-shepherd:msgHdlr IND <-- ZDO:mgmtPermitJoinRsp +26ms zigbee-shepherd:init Loading devices from database done. +430ms zigbee-shepherd zigbee-shepherd is _ready and _enabled +2ms zigbee2mqtt:info 26/11/2018, 20:39:05 zigbee-shepherd started zigbee2mqtt:info 26/11/2018, 20:39:05 Coordinator firmware version: '20180815' zigbee2mqtt:debug 26/11/2018, 20:39:05 zigbee-shepherd info: {"enabled":true,"net":{"state":"Coordinator","channel":26,"panId":"0x1a62","extPanId":"0xdddddddddddddddd","ieeeAddr":"0x00124b0018eceb2e","nwkAddr":0},"firmware":{"transportrev":2,"product":0,"version":"2.6.3","revision":20180815},"startTime":1543250345,"joinTimeLeft":0} zigbee2mqtt:info 26/11/2018, 20:39:05 Currently 0 devices are joined: zigbee2mqtt:warn 26/11/2018, 20:39:05 `permit_join` set to `true` in configuration.yaml. zigbee2mqtt:warn 26/11/2018, 20:39:05 Allowing new devices to join. zigbee2mqtt:warn 26/11/2018, 20:39:05 Set `permit_join` to `false` once you joined all devices. zigbee2mqtt:info 26/11/2018, 20:39:05 Zigbee: allowing new devices to join. zigbee2mqtt:info 26/11/2018, 20:39:05 Connecting to MQTT server at mqtt://192.168.1.222 zigbee-shepherd:request REQ --> ZDO:mgmtPermitJoinReq +407ms zigbee2mqtt:info 26/11/2018, 20:39:05 zigbee-shepherd ready zigbee-shepherd:msgHdlr IND <-- ZDO:permitJoinInd +308ms zigbee-shepherd:msgHdlr IND <-- ZDO:mgmtPermitJoinRsp +1ms zigbee2mqtt:info 26/11/2018, 20:39:05 Connected to MQTT server zigbee2mqtt:info 26/11/2018, 20:39:05 MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online' zigbee2mqtt:debug 26/11/2018, 20:39:05 Soft reset timeout disabled zigbee-shepherd:msgHdlr IND <-- ZDO:tcDeviceInd +17s zigbee-shepherd spinlock: false [] +763ms zigbee-shepherd:request REQ --> ZDO:nodeDescReq +12ms zigbee-shepherd:msgHdlr IND <-- ZDO:endDeviceAnnceInd +4ms zigbee-shepherd:msgHdlr IND <-- ZDO:nodeDescRsp +95ms zigbee-shepherd:request REQ --> ZDO:activeEpReq +2ms zigbee-shepherd:msgHdlr IND <-- ZDO:activeEpRsp +113ms zigbee-shepherd:request REQ --> ZDO:simpleDescReq +1ms zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +120ms zigbee-shepherd:request REQ --> AF:dataRequest, transId: 1 +23ms zigbee-shepherd:request RSP <-- AF:dataRequest, status: 0 +14ms zigbee-shepherd:af dispatchIncomingMsg(): type: dataConfirm, msg: [object Object] +81ms zigbee-shepherd:msgHdlr IND <-- AF:dataConfirm, transId: 1 +1ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: [object Object] +7ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +21ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: [object Object] +1ms zigbee-shepherd Identified Device: { manufacturer: LIVOLOTI0001 , product: TI0001 } +3ms zigbee-shepherd:request REQ --> AF:dataRequest, transId: 2 +22ms zigbee-shepherd:request RSP <-- AF:dataRequest, status: 0 +13ms zigbee-shepherd:af dispatchIncomingMsg(): type: dataConfirm, msg: [object Object] +53ms zigbee-shepherd:msgHdlr IND <-- AF:dataConfirm, transId: 2 +1ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: [object Object] +6ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +5ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: [object Object] +1ms zigbee2mqtt:debug 26/11/2018, 20:39:23 Received zigbee message of type 'devInterview' with data '"0x00124b000befc0b9"' zigbee2mqtt:info 26/11/2018, 20:39:23 Connecting with device... zigbee2mqtt:info 26/11/2018, 20:39:23 MQTT publish, topic: 'zigbee2mqtt/bridge/log', payload: '{"type":"pairing","message":"connecting with device"}' zigbee-shepherd:request REQ --> AF:dataRequest, transId: 3 +12ms zigbee-shepherd:request RSP <-- AF:dataRequest, status: 0 +13ms zigbee-shepherd:af dispatchIncomingMsg(): type: dataConfirm, msg: [object Object] +91ms zigbee-shepherd:msgHdlr IND <-- AF:dataConfirm, transId: 3 +1ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: [object Object] +4ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +4ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: [object Object] +1ms zigbee2mqtt:debug 26/11/2018, 20:39:24 Received zigbee message of type 'devInterview' with data '"0x00124b000befc0b9"' zigbee2mqtt:info 26/11/2018, 20:39:24 Connecting with device... zigbee2mqtt:info 26/11/2018, 20:39:24 MQTT publish, topic: 'zigbee2mqtt/bridge/log', payload: '{"type":"pairing","message":"connecting with device"}' zigbee-shepherd:request REQ --> AF:dataRequest, transId: 4 +8ms zigbee-shepherd:request RSP <-- AF:dataRequest, status: 0 +14ms zigbee-shepherd:af dispatchIncomingMsg(): type: dataConfirm, msg: [object Object] +90ms zigbee-shepherd:msgHdlr IND <-- AF:dataConfirm, transId: 4 +1ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: [object Object] +10ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +7ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: [object Object] +2ms zigbee2mqtt:debug 26/11/2018, 20:39:24 Received zigbee message of type 'devInterview' with data '"0x00124b000befc0b9"' zigbee2mqtt:info 26/11/2018, 20:39:24 Connecting with device... zigbee2mqtt:info 26/11/2018, 20:39:24 MQTT publish, topic: 'zigbee2mqtt/bridge/log', payload: '{"type":"pairing","message":"connecting with device"}' zigbee-shepherd Device: 0x00124b000befc0b9 join the network. +28ms zigbee2mqtt:debug 26/11/2018, 20:39:24 Received zigbee message of type 'devIncoming' with data '"0x00124b000befc0b9"' of device 'TI0001 ' (0x00124b000befc0b9) zigbee2mqtt:info 26/11/2018, 20:39:24 Device incoming... zigbee2mqtt:info 26/11/2018, 20:39:24 MQTT publish, topic: 'zigbee2mqtt/bridge/log', payload: '{"type":"pairing","message":"device incoming"}' zigbee2mqtt:info 26/11/2018, 20:39:24 New device with address 0x00124b000befc0b9 connected! zigbee2mqtt:info 26/11/2018, 20:39:24 MQTT publish, topic: 'zigbee2mqtt/bridge/log', payload: '{"type":"device_connected","message":"0x00124b000befc0b9"}' zigbee2mqtt:error 26/11/2018, 20:39:24 Failed to configure 0x00124b000befc0b9 0x00124b000befc0b9 zigbee2mqtt:debug 26/11/2018, 20:39:24 Received zigbee message of type 'devStatus' with data '"online"' of device 'TI0001 ' (0x00124b000befc0b9) ^C zigbee2mqtt:debug 26/11/2018, 20:40:24 Saving state to file /opt/zigbee2mqtt/data/state.json zigbee2mqtt:info 26/11/2018, 20:40:24 MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'offline' zigbee2mqtt:info 26/11/2018, 20:40:24 Disconnecting from MQTT server zigbee-shepherd zigbee-shepherd is stopping. +1m zigbee-shepherd:request REQ --> ZDO:mgmtPermitJoinReq +5ms zigbee-shepherd zigbee-shepherd is stopped. +15ms zigbee2mqtt:info 26/11/2018, 20:40:24 zigbee-shepherd stopped