Merge pull request #8976 from s-hadinger/zigbee_ezsp_july_25

Zigbee EZSP improvements and reduced logging

tasmota/i18n.h

@@ -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"

tasmota/tasmota_template.h

@@ -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
+    GPIO_ZIGBEE_RST,  // GPIO04 Zigbee Reset
-    0,
+    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
   }

tasmota/xdrv_23_zigbee_0_constants.ino

@@ -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"

tasmota/xdrv_23_zigbee_7_statemachine.ino

@@ -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,

tasmota/xdrv_23_zigbee_8_parsers.ino

@@ -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;
   }

tasmota/xdrv_23_zigbee_9_serial.ino

@@ -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);
+        AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_ZIGBEE "{\"" 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
-        }
         // 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);