Zigbee EZSP improvements and reduced logging

This commit is contained in:
Stephan Hadinger 2020-07-25 15:40:42 +02:00
parent 38179062ae
commit 781cb4d9c7
6 changed files with 162 additions and 33 deletions

View File

@ -514,6 +514,7 @@
#define D_CMND_ZIGBEE_EZSP_SEND "EZSPSend"
#define D_CMND_ZIGBEE_EZSP_SEND_RAW "EZSPSendRaw"
#define D_JSON_ZIGBEE_STATE "ZbState"
#define D_JSON_ZIGBEE_ROUTE_ERROR "ZbRouteError"
#define D_JSON_ZIGBEEZNPRECEIVED "ZbZNPReceived"
#define D_JSON_ZIGBEE_EZSP_RECEIVED "ZbEZSPReceived"
#define D_JSON_ZIGBEEZNPSENT "ZbZNPSent"
@ -549,6 +550,7 @@
#define D_JSON_ZIGBEE_UNBIND "ZbUnbind"
#define D_CMND_ZIGBEE_BIND_STATE "BindState"
#define D_JSON_ZIGBEE_BIND_STATE "ZbBindState"
#define D_JSON_ZIGBEE_PARENT "ZbParent"
#define D_CMND_ZIGBEE_PING "Ping"
#define D_JSON_ZIGBEE_PING "ZbPing"
#define D_JSON_ZIGBEE_IEEE "IEEEAddr"

View File

@ -2283,21 +2283,22 @@ const mytmplt kModules[MAXMODULE] PROGMEM = {
0, 0, 0, 0
},
{ // SONOFF_ZB_BRIDGE - Sonoff Zigbee Bridge (ESP8266)
GPIO_LED1_INV, // GPIO00 Led (0 = On, 1 = Off) - Status
GPIO_LED1_INV, // GPIO00 Green Led (0 = On, 1 = Off) - Traffic between ESP and EFR
GPIO_ZIGBEE_TX, // GPIO01 Zigbee Serial control
0, // GPIO02
GPIO_ZIGBEE_RX, // GPIO03 Zigbee Serial control
GPIO_ZIGBEE_RST, // GPIO04 ZIgbee Reset
0,
GPIO_ZIGBEE_RST, // GPIO04 Zigbee Reset
0, // GPIO05 EFR32 Bootloader mode (drive Low for Gecko Bootloader, inactive or high for Zigbee EmberZNet)
// GPIO06 (SD_CLK Flash)
// GPIO07 (SD_DATA0 Flash QIO/DIO/DOUT)
// GPIO08 (SD_DATA1 Flash QIO/DIO/DOUT)
0, // GPIO09 (SD_DATA2 Flash QIO)
0, // GPIO10 (SD_DATA3 Flash QIO)
// GPIO11 (SD_CMD Flash)
0,
GPIO_I2C_SDA, // GPIO12 I2C SDA - connected to 512KB EEPROM
GPIO_LEDLNK_INV, // GPIO13 Blue Led (0 = On, 1 = Off) - Link status
0, 0,
GPIO_I2C_SCL, // GPIO14 I2C SCL - connected to 512KB EEPROM
0, // GPIO15 connected to IO15 pad, also used for logging
GPIO_KEY1, // GPIO16 Button
0
}

View File

@ -1105,12 +1105,6 @@ enum ZCL_Global_Commands {
#define ZF(s) static const char ZS_ ## s[] PROGMEM = #s;
#define Z(s) ZS_ ## s
typedef struct Z_StatusLine {
uint32_t status; // no need to use uint8_t since it uses 32 bits anyways
const char * status_msg;
} Z_StatusLine;
// ZDP Enumeration, see Zigbee spec 2.4.5
String getZDPStatusMessage(uint8_t status) {
static const char StatusMsg[] PROGMEM = "SUCCESS|INV_REQUESTTYPE|DEVICE_NOT_FOUND|INVALID_EP|NOT_ACTIVE|NOT_SUPPORTED"

View File

@ -710,7 +710,7 @@ ZBM(ZBS_SET_POLICY_02, EZSP_setPolicy, 0x00 /*high*/, EZSP_UNICAST_REPLIES_PO
ZBM(ZBS_SET_POLICY_03, EZSP_setPolicy, 0x00 /*high*/, EZSP_POLL_HANDLER_POLICY,
EZSP_POLL_HANDLER_IGNORE) // 55000330
ZBM(ZBS_SET_POLICY_04, EZSP_setPolicy, 0x00 /*high*/, EZSP_MESSAGE_CONTENTS_IN_CALLBACK_POLICY,
EZSP_MESSAGE_TAG_AND_CONTENTS_IN_CALLBACK) // 55000441
EZSP_MESSAGE_TAG_ONLY_IN_CALLBACK) // 55000440
ZBM(ZBS_SET_POLICY_05, EZSP_setPolicy, 0x00 /*high*/, EZSP_TC_KEY_REQUEST_POLICY,
EZSP_ALLOW_TC_KEY_REQUESTS_AND_SEND_CURRENT_KEY) // 55000551
ZBM(ZBS_SET_POLICY_06, EZSP_setPolicy, 0x00 /*high*/, EZSP_APP_KEY_REQUEST_POLICY,

View File

@ -115,6 +115,43 @@ int32_t EZ_NetworkParameters(int32_t res, class SBuffer &buf) {
return res;
}
//
// Handle a "incomingRouteErrorHandler" incoming message
//
int32_t EZ_RouteError(int32_t res, const class SBuffer &buf) {
uint8_t status = buf.get8(2);
uint16_t shortaddr = buf.get16(3);
Response_P(PSTR("{\"" D_JSON_ZIGBEE_ROUTE_ERROR "\":{"
"\"ShortAddr\":\"0x%04X\",\"" D_JSON_ZIGBEE_STATUS "\":%d,\"" D_JSON_ZIGBEE_STATUS_MSG "\":\"0x%s\"}}"),
shortaddr, status, "");
MqttPublishPrefixTopicRulesProcess_P(RESULT_OR_TELE, PSTR(D_JSON_ZIGBEE_STATE));
return -1;
}
//
// Handle a "permitJoining" incoming message
//
int32_t EZ_PermitJoinRsp(int32_t res, const class SBuffer &buf) {
uint8_t status = buf.get8(2);
Response_P(PSTR("{\"" D_JSON_ZIGBEE_STATE "\":{"
"\"Status\":%d,\"Message\":\"%s"),
(0 == status) ? ZIGBEE_STATUS_PERMITJOIN_OPEN_60 : ZIGBEE_STATUS_PERMITJOIN_CLOSE,
(0 == status) ? PSTR("Pairing mode enabled") : PSTR("Pairing mode error")
);
if (status) {
ResponseAppend_P("0x%02X", status);
}
ResponseAppend_P(PSTR("\"}}"));
MqttPublishPrefixTopicRulesProcess_P(RESULT_OR_TELE, PSTR(D_JSON_ZIGBEE_STATE));
return -1;
}
#endif // USE_ZIGBEE_EZSP
/*********************************************************************************************\
@ -785,6 +822,72 @@ int32_t Z_MgmtBindRsp(int32_t res, const class SBuffer &buf) {
return -1;
}
//
// Handle Parent Annonce Rsp incoming message
//
// rsp: true = ZDO_Parent_annce_rsp, false = ZDO_Parent_annce
int32_t Z_ParentAnnceRsp(int32_t res, const class SBuffer &buf, bool rsp) {
#ifdef USE_ZIGBEE_ZNP
// uint16_t shortaddr = buf.get16(2);
// uint8_t status = buf.get8(4);
// uint8_t bind_total = buf.get8(5);
// uint8_t bind_start = buf.get8(6);
// uint8_t bind_len = buf.get8(7);
// const size_t prefix_len = 8;
#endif // USE_ZIGBEE_ZNP
#ifdef USE_ZIGBEE_EZSP
size_t prefix_len;
uint8_t status;
uint8_t num_children;
uint16_t shortaddr = buf.get16(buf.len()-2);
if (rsp) {
status = buf.get8(0);
num_children = buf.get8(1);
prefix_len = 2;
} else {
status = 0;
num_children = buf.get8(0);
prefix_len = 1;
}
#endif // USE_ZIGBEE_EZSP
const char * friendlyName = zigbee_devices.getFriendlyName(shortaddr);
Response_P(PSTR("{\"" D_JSON_ZIGBEE_PARENT "\":{\"" D_JSON_ZIGBEE_DEVICE "\":\"0x%04X\""), shortaddr);
if (friendlyName) {
ResponseAppend_P(PSTR(",\"" D_JSON_ZIGBEE_NAME "\":\"%s\""), friendlyName);
}
if (rsp) {
ResponseAppend_P(PSTR(",\"" D_JSON_ZIGBEE_STATUS "\":%d"
",\"" D_JSON_ZIGBEE_STATUS_MSG "\":\"%s\""
), status, getZigbeeStatusMessage(status).c_str());
}
ResponseAppend_P(PSTR(",\"Children\":%d"
",\"ChildInfo\":["
), num_children);
uint32_t idx = prefix_len;
for (uint32_t i = 0; i < num_children; i++) {
if (idx + 8 > buf.len()) { break; } // overflow, frame size is between 14 and 21
uint64_t child_ieee = buf.get64(idx);
idx += 8;
if (i > 0) {
ResponseAppend_P(PSTR(","));
}
char hex[20];
Uint64toHex(child_ieee, hex, 64);
ResponseAppend_P(PSTR("\"0x%s\""), hex);
}
ResponseAppend_P(PSTR("]}}"));
MqttPublishPrefixTopicRulesProcess_P(RESULT_OR_TELE, PSTR(D_JSON_ZIGBEE_BIND_STATE));
return -1;
}
/*********************************************************************************************\
* Send specific ZNP messages
\*********************************************************************************************/
@ -1051,6 +1154,14 @@ int32_t EZ_IncomingMessage(int32_t res, const class SBuffer &buf) {
return Z_UnbindRsp(res, zdo_buf);
case ZDO_Mgmt_Bind_rsp:
return Z_MgmtBindRsp(res, zdo_buf);
case ZDO_Parent_annce:
return Z_ParentAnnceRsp(res, zdo_buf, false);
case ZDO_Parent_annce_rsp:
return Z_ParentAnnceRsp(res, zdo_buf, true);
default:
// TODO move later to LOG_LEVEL_DEBUG
AddLog_P2(LOG_LEVEL_INFO, PSTR("ZIG: Internal ZDO message 0x%04X sent from 0x%04X %s"), clusterid, srcaddr, wasbroadcast ? PSTR("(broadcast)") : "");
break;
}
} else {
bool defer_attributes = false; // do we defer attributes reporting to coalesce
@ -1106,6 +1217,12 @@ int32_t EZ_Recv_Default(int32_t res, const class SBuffer &buf) {
case EZSP_trustCenterJoinHandler:
return EZ_ReceiveTCJoinHandler(res, buf);
break;
case EZSP_incomingRouteErrorHandler:
return EZ_RouteError(res, buf);
break;
case EZSP_permitJoining:
return EZ_PermitJoinRsp(res, buf);
break;
}
return -1;
}

View File

@ -118,7 +118,7 @@ void ZigbeeInputLoop(void) {
char hex_char[(zigbee_buffer->len() * 2) + 2];
ToHex_P((unsigned char*)zigbee_buffer->getBuffer(), zigbee_buffer->len(), hex_char, sizeof(hex_char));
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "Bytes follow_read_metric = %0d"), ZigbeeSerial->getLoopReadMetric());
// AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "Bytes follow_read_metric = %0d"), ZigbeeSerial->getLoopReadMetric());
// buffer received, now check integrity
if (zigbee_buffer->len() != zigbee_frame_len) {
// Len is not correct, log and reject frame
@ -163,7 +163,7 @@ void ZigbeeInputLoop(void) {
yield();
uint8_t zigbee_in_byte = ZigbeeSerial->read();
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: ZbInput byte=0x%02X len=%d"), zigbee_in_byte, zigbee_buffer->len());
// AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: ZbInput byte=0x%02X len=%d"), zigbee_in_byte, zigbee_buffer->len());
// if (0 == zigbee_buffer->len()) { // make sure all variables are correctly initialized
// escape = false;
@ -175,13 +175,13 @@ void ZigbeeInputLoop(void) {
}
if (ZIGBEE_EZSP_ESCAPE == zigbee_in_byte) {
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: Escape byte received"));
// AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: Escape byte received"));
escape = true;
continue;
}
if (ZIGBEE_EZSP_CANCEL == zigbee_in_byte) {
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: ZbInput byte=0x1A, cancel byte received, discarding %d bytes"), zigbee_buffer->len());
// AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: ZbInput byte=0x1A, cancel byte received, discarding %d bytes"), zigbee_buffer->len());
zigbee_buffer->setLen(0); // empty buffer
escape = false;
frame_complete = false;
@ -215,7 +215,7 @@ void ZigbeeInputLoop(void) {
char hex_char[frame_len * 2 + 2];
ToHex_P((unsigned char*)zigbee_buffer->getBuffer(), zigbee_buffer->len(), hex_char, sizeof(hex_char));
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "Bytes follow_read_metric = %0d"), ZigbeeSerial->getLoopReadMetric());
// AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "Bytes follow_read_metric = %0d"), ZigbeeSerial->getLoopReadMetric());
if ((frame_complete) && (frame_len >= 3)) {
// frame received and has at least 3 bytes (without EOF), checking CRC
// AddLog_P2(LOG_LEVEL_INFO, PSTR(D_JSON_ZIGBEE_EZSP_RECEIVED ": received raw frame %s"), hex_char);
@ -253,12 +253,7 @@ void ZigbeeInputLoop(void) {
}
ToHex_P((unsigned char*)ezsp_buffer.getBuffer(), ezsp_buffer.len(), hex_char, sizeof(hex_char));
Response_P(PSTR("{\"" D_JSON_ZIGBEE_EZSP_RECEIVED "2\":\"%s\"}"), hex_char);
if (Settings.flag3.tuya_serial_mqtt_publish) {
MqttPublishPrefixTopicRulesProcess_P(TELE, PSTR(D_RSLT_SENSOR));
} else {
AddLog_P2(LOG_LEVEL_DEBUG, PSTR(D_LOG_ZIGBEE "%s"), mqtt_data); // TODO move to LOG_LEVEL_DEBUG when stable
}
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "{\"" D_JSON_ZIGBEE_EZSP_RECEIVED "2\":\"%s\"}"), hex_char);
// now process the message
ZigbeeProcessInputRaw(ezsp_buffer);
}
@ -491,7 +486,7 @@ void ZigbeeEZSPSendRaw(const uint8_t *msg, size_t len, bool send_cancel) {
// Now send a MQTT message to report the sent message
char hex_char[(len * 2) + 2];
AddLog_P2(LOG_LEVEL_DEBUG, PSTR(D_LOG_ZIGBEE D_JSON_ZIGBEE_EZSP_SENT_RAW " %s"),
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE D_JSON_ZIGBEE_EZSP_SENT_RAW " %s"),
ToHex_P(msg, len, hex_char, sizeof(hex_char)));
}
@ -500,7 +495,7 @@ void ZigbeeEZSPSendRaw(const uint8_t *msg, size_t len, bool send_cancel) {
void ZigbeeEZSPSendCmd(const uint8_t *msg, size_t len) {
char hex_char[len*2 + 2];
ToHex_P(msg, len, hex_char, sizeof(hex_char));
AddLog_P2(LOG_LEVEL_INFO, PSTR(D_LOG_ZIGBEE "ZbEZSPSend %s"), hex_char);
AddLog_P2(LOG_LEVEL_DEBUG, PSTR(D_LOG_ZIGBEE "ZbEZSPSend %s"), hex_char);
SBuffer cmd(len+3); // prefix with seq number (1 byte) and frame control bytes (2 bytes)
@ -517,7 +512,7 @@ void ZigbeeEZSPSendCmd(const uint8_t *msg, size_t len) {
void ZigbeeEZSPSendDATA_frm(bool send_cancel, uint8_t to_frm, uint8_t from_ack) {
SBuffer *buf = EZSP_Serial.to_packets[to_frm];
if (!buf) {
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: Buffer for packet %d is not allocated"), EZSP_Serial.to_send);
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: Buffer for packet %d is not allocated"), EZSP_Serial.to_send);
return;
}
@ -534,7 +529,7 @@ void ZigbeeEZSPSendDATA(const uint8_t *msg, size_t len) {
buf->add8(0x00); // placeholder for control_byte
buf->addBuffer(msg, len);
//
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: adding packet to_send, to_ack:%d, to_send:%d, to_end:%d"),
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: adding packet to_send, to_ack:%d, to_send:%d, to_end:%d"),
EZSP_Serial.to_ack, EZSP_Serial.to_send, EZSP_Serial.to_end);
uint8_t to_frm = EZSP_Serial.to_end;
if (EZSP_Serial.to_packets[to_frm]) {
@ -579,7 +574,27 @@ int32_t ZigbeeProcessInputEZSP(class SBuffer &buf) {
if (Settings.flag3.tuya_serial_mqtt_publish) {
MqttPublishPrefixTopicRulesProcess_P(TELE, PSTR(D_RSLT_SENSOR));
} else {
AddLog_P2(LOG_LEVEL_INFO, PSTR(D_LOG_ZIGBEE "%s"), mqtt_data); // TODO move to LOG_LEVEL_DEBUG when stable
// demote less interesting messages to LOG_LEVEL_DEBUG
uint32_t log_level = LOG_LEVEL_INFO;
switch (buf.get16(0)) {
case EZSP_version: // 0000
case EZSP_addEndpoint: // 0200
case EZSP_setConcentrator: // 1000
case EZSP_networkInit: // 1700
case EZSP_stackStatusHandler: // 1900
case EZSP_permitJoining: // 2200
case EZSP_getEui64: // 2600
case EZSP_getNodeId: // 2700
case EZSP_sendUnicast: // 3400
case EZSP_sendBroadcast: // 3600
case EZSP_messageSentHandler: // 3F00
case EZSP_setConfigurationValue: // 5300
case EZSP_setPolicy: // 5500
case EZSP_setMulticastTableEntry: // 6400
log_level = LOG_LEVEL_DEBUG;
break;
}
AddLog_P2(log_level, PSTR(D_LOG_ZIGBEE "%s"), mqtt_data); // TODO move to LOG_LEVEL_DEBUG when stable
}
// Pass message to state machine
@ -589,14 +604,14 @@ int32_t ZigbeeProcessInputEZSP(class SBuffer &buf) {
// Check if we advanced in the ACKed frames, and free from memory packets acknowledged
void EZSP_HandleAck(uint8_t new_ack) {
if (EZSP_Serial.to_ack != new_ack) { // new ack receveid
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: new ack/data received, was %d now %d"), EZSP_Serial.to_ack, new_ack);
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: new ack/data received, was %d now %d"), EZSP_Serial.to_ack, new_ack);
uint32_t i = EZSP_Serial.to_ack;
do {
if (EZSP_Serial.to_packets[i]) {
delete EZSP_Serial.to_packets[i];
EZSP_Serial.to_packets[i] = nullptr;
}
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: freeing packet %d from memory"), i);
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: freeing packet %d from memory"), i);
i = (i + 1) & 0x07;
} while (i != new_ack);
EZSP_Serial.to_ack = new_ack;
@ -617,10 +632,10 @@ int32_t ZigbeeProcessInputRaw(class SBuffer &buf) {
} else if (frame_type == 0xA0) {
// NAK
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: Received NAK %d, to_ack:%d, to_send:%d, to_end:%d"),
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: Received NAK %d, to_ack:%d, to_send:%d, to_end:%d"),
ack_num, EZSP_Serial.to_ack, EZSP_Serial.to_send, EZSP_Serial.to_end);
EZSP_Serial.to_send = ack_num;
AddLog_P2(LOG_LEVEL_INFO, PSTR("ZIG: NAK, resending packet %d"), ack_num);
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: NAK, resending packet %d"), ack_num);
} else if (control_byte == 0xC1) {
// RSTACK
@ -844,7 +859,7 @@ void ZigbeeOutputLoop(void) {
#ifdef USE_ZIGBEE_EZSP
// while (EZSP_Serial.to_send != EZSP_Serial.to_end) {
if (EZSP_Serial.to_send != EZSP_Serial.to_end) { // we send only one packet per tick to lower the chance of NAK
AddLog_P2(LOG_LEVEL_DEBUG, PSTR("ZIG: Something to_send, to_ack:%d, to_send:%d, to_end:%d"),
AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR("ZIG: Something to_send, to_ack:%d, to_send:%d, to_end:%d"),
EZSP_Serial.to_ack, EZSP_Serial.to_send, EZSP_Serial.to_end);
// we have a frame waiting to be sent
ZigbeeEZSPSendDATA_frm(true, EZSP_Serial.to_send, EZSP_Serial.from_ack);