diff --git a/CHANGELOG.md b/CHANGELOG.md index 27ecf079f..ef251e501 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,9 @@ All notable changes to this project will be documented in this file. - Milliseconds to console output (#10152) - Support for P9813 RGB Led MOSFET controller (#10104) +### Fixed +- Redesign syslog and mqttlog using log buffer (#10164) + ## [Released] ## [9.2.0] 20201216 diff --git a/RELEASENOTES.md b/RELEASENOTES.md index 45e8b854a..04faed44f 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -61,10 +61,5 @@ The attached binaries can also be downloaded from http://ota.tasmota.com/tasmota - Milliseconds to console output (#10152) - Support for P9813 RGB Led MOSFET controller (#10104) -### Breaking Changed - -### Changed - ### Fixed - -### Removed +- Redesign syslog and mqttlog using log buffer (#10164) diff --git a/tasmota/support.ino b/tasmota/support.ino index 8c2aadeb8..b1d30b41d 100644 --- a/tasmota/support.ino +++ b/tasmota/support.ino @@ -1899,32 +1899,6 @@ void SetSyslog(uint32_t loglevel) TasmotaGlobal.syslog_timer = 0; } -#ifdef USE_WEBSERVER -void GetLog(uint32_t idx, char** entry_pp, size_t* len_p) -{ - char* entry_p = nullptr; - size_t len = 0; - - if (idx) { - char* it = TasmotaGlobal.web_log; - do { - uint32_t cur_idx = *it; - it++; - size_t tmp = strchrspn(it, '\1'); - tmp++; // Skip terminating '\1' - if (cur_idx == idx) { // Found the requested entry - len = tmp; - entry_p = it; - break; - } - it += tmp; - } while (it < TasmotaGlobal.web_log + WEB_LOG_SIZE && *it != '\0'); - } - *entry_pp = entry_p; - *len_p = len; -} -#endif // USE_WEBSERVER - void Syslog(void) { // Destroys TasmotaGlobal.log_data @@ -1935,14 +1909,14 @@ void Syslog(void) WiFi.hostByName(SettingsText(SET_SYSLOG_HOST), syslog_host_addr); // If sleep enabled this might result in exception so try to do it once using hash } if (PortUdp.beginPacket(syslog_host_addr, Settings.syslog_port)) { - char syslog_preamble[64]; // Hostname + Id + char syslog_preamble[64]; // Hostname + Id snprintf_P(syslog_preamble, sizeof(syslog_preamble), PSTR("%s ESP-"), NetworkHostname()); memmove(TasmotaGlobal.log_data + strlen(syslog_preamble), TasmotaGlobal.log_data, sizeof(TasmotaGlobal.log_data) - strlen(syslog_preamble)); TasmotaGlobal.log_data[sizeof(TasmotaGlobal.log_data) -1] = '\0'; memcpy(TasmotaGlobal.log_data, syslog_preamble, strlen(syslog_preamble)); PortUdp_write(TasmotaGlobal.log_data, strlen(TasmotaGlobal.log_data)); PortUdp.endPacket(); - delay(1); // Add time for UDP handling (#5512) + delay(1); // Add time for UDP handling (#5512) } else { TasmotaGlobal.syslog_level = 0; TasmotaGlobal.syslog_timer = SYSLOG_TIMER; @@ -1950,8 +1924,57 @@ void Syslog(void) } } -void AddLog(uint32_t loglevel) -{ +void SyslogAsync(void) { + static uint32_t counter = 1; + + if (!TasmotaGlobal.syslog_level || + (counter == TasmotaGlobal.web_log_index) || + TasmotaGlobal.global_state.network_down) { return; } + + do { + char* tmp; + size_t len; + uint32_t loglevel = GetLog(counter, &tmp, &len); + if ((len > 13) && + (loglevel <= TasmotaGlobal.syslog_level) && + (TasmotaGlobal.masterlog_level <= TasmotaGlobal.syslog_level)) { + strlcpy(TasmotaGlobal.log_data, tmp +13, len -13); // Skip mxtime + Syslog(); + } + counter++; + counter &= 0xFF; + if (!counter) { counter++; } // Skip 0 as it is not allowed + } while (counter != TasmotaGlobal.web_log_index); +} + +uint32_t GetLog(uint32_t idx, char** entry_pp, size_t* len_p) { + char* entry_p = nullptr; + size_t len = 0; + uint32_t loglevel = 0; + if (idx) { + char* it = TasmotaGlobal.web_log; + do { + uint32_t cur_idx = *it; + it++; + size_t tmp = strchrspn(it, '\1'); + tmp++; // Skip terminating '\1' + if (cur_idx == idx) { // Found the requested entry + loglevel = *it - '0'; + it++; // Skip loglevel + len = tmp -1; + entry_p = it; + break; + } + it += tmp; + } while (it < TasmotaGlobal.web_log + WEB_LOG_SIZE && *it != '\0'); + } + *entry_pp = entry_p; + *len_p = len; + + return loglevel; +} + +void AddLog(uint32_t loglevel) { // char mxtime[10]; // "13:45:21 " // snprintf_P(mxtime, sizeof(mxtime), PSTR("%02d" D_HOUR_MINUTE_SEPARATOR "%02d" D_MINUTE_SECOND_SEPARATOR "%02d "), RtcTime.hour, RtcTime.minute, RtcTime.second); char mxtime[14]; // "13:45:21.999 " @@ -1961,41 +1984,34 @@ void AddLog(uint32_t loglevel) (TasmotaGlobal.masterlog_level <= TasmotaGlobal.seriallog_level)) { Serial.printf("%s%s\r\n", mxtime, TasmotaGlobal.log_data); } -#ifdef USE_WEBSERVER - if (Settings.webserver && - (loglevel <= Settings.weblog_level) && - (TasmotaGlobal.masterlog_level <= Settings.weblog_level)) { + + uint32_t highest_loglevel = Settings.weblog_level; + if (Settings.mqttlog_level > highest_loglevel) { highest_loglevel = Settings.mqttlog_level; } + if (TasmotaGlobal.syslog_level > highest_loglevel) { highest_loglevel = TasmotaGlobal.syslog_level; } + if ((loglevel <= highest_loglevel) && // Log only when needed + (TasmotaGlobal.masterlog_level <= highest_loglevel)) { // Delimited, zero-terminated buffer of log lines. - // Each entry has this format: [index][log data]['\1'] + // Each entry has this format: [index][loglevel][log data]['\1'] TasmotaGlobal.web_log_index &= 0xFF; if (!TasmotaGlobal.web_log_index) { - TasmotaGlobal.web_log_index++; // Index 0 is not allowed as it is the end of char string + TasmotaGlobal.web_log_index++; // Index 0 is not allowed as it is the end of char string } while (TasmotaGlobal.web_log_index == TasmotaGlobal.web_log[0] || // If log already holds the next index, remove it strlen(TasmotaGlobal.web_log) + strlen(TasmotaGlobal.log_data) + strlen(mxtime) + 4 > WEB_LOG_SIZE) // 4 = web_log_index + '\1' + '\0' { char* it = TasmotaGlobal.web_log; - it++; // Skip web_log_index - it += strchrspn(it, '\1'); // Skip log line - it++; // Skip delimiting "\1" + it++; // Skip web_log_index + it += strchrspn(it, '\1'); // Skip log line + it++; // Skip delimiting "\1" memmove(TasmotaGlobal.web_log, it, WEB_LOG_SIZE -(it-TasmotaGlobal.web_log)); // Move buffer forward to remove oldest log line } - snprintf_P(TasmotaGlobal.web_log, sizeof(TasmotaGlobal.web_log), PSTR("%s%c%s%s\1"), TasmotaGlobal.web_log, TasmotaGlobal.web_log_index++, mxtime, TasmotaGlobal.log_data); + snprintf_P(TasmotaGlobal.web_log, sizeof(TasmotaGlobal.web_log), PSTR("%s%c%c%s%s\1"), + TasmotaGlobal.web_log, TasmotaGlobal.web_log_index++, '0'+loglevel, mxtime, TasmotaGlobal.log_data); TasmotaGlobal.web_log_index &= 0xFF; if (!TasmotaGlobal.web_log_index) { - TasmotaGlobal.web_log_index++; // Index 0 is not allowed as it is the end of char string + TasmotaGlobal.web_log_index++; // Index 0 is not allowed as it is the end of char string } } -#endif // USE_WEBSERVER - if (Settings.flag.mqtt_enabled && // SetOption3 - Enable MQTT - !TasmotaGlobal.global_state.mqtt_down && - (loglevel <= Settings.mqttlog_level) && - (TasmotaGlobal.masterlog_level <= Settings.mqttlog_level)) { MqttPublishLogging(mxtime); } - - if (!TasmotaGlobal.global_state.network_down && - (loglevel <= TasmotaGlobal.syslog_level) && - (TasmotaGlobal.masterlog_level <= TasmotaGlobal.syslog_level)) { Syslog(); } - TasmotaGlobal.prepped_loglevel = 0; } diff --git a/tasmota/support_rtc.ino b/tasmota/support_rtc.ino index 390a1946f..294303026 100644 --- a/tasmota/support_rtc.ino +++ b/tasmota/support_rtc.ino @@ -392,7 +392,7 @@ void RtcSecond(void) Rtc.standard_time = RuleToTime(Settings.tflag[0], RtcTime.year); // Do not use AddLog_P( here (interrupt routine) if syslog or mqttlog is enabled. UDP/TCP will force exception 9 - PrepLog_P(LOG_LEVEL_DEBUG, PSTR("RTC: " D_UTC_TIME " %s, " D_DST_TIME " %s, " D_STD_TIME " %s"), + AddLog_P(LOG_LEVEL_DEBUG, PSTR("RTC: " D_UTC_TIME " %s, " D_DST_TIME " %s, " D_STD_TIME " %s"), GetDateAndTime(DT_UTC).c_str(), GetDateAndTime(DT_DST).c_str(), GetDateAndTime(DT_STD).c_str()); if (Rtc.local_time < START_VALID_TIME) { // 2016-01-01 @@ -407,7 +407,7 @@ void RtcSecond(void) if ((Rtc.utc_time > (2 * 60 * 60)) && (last_sync < Rtc.utc_time - (2 * 60 * 60))) { // Every two hours a warning // Do not use AddLog_P( here (interrupt routine) if syslog or mqttlog is enabled. UDP/TCP will force exception 9 - PrepLog_P(LOG_LEVEL_DEBUG, PSTR("RTC: Not synced")); + AddLog_P(LOG_LEVEL_DEBUG, PSTR("RTC: Not synced")); last_sync = Rtc.utc_time; } diff --git a/tasmota/support_tasmota.ino b/tasmota/support_tasmota.ino index 02c6a00ca..47ac7f3ea 100644 --- a/tasmota/support_tasmota.ino +++ b/tasmota/support_tasmota.ino @@ -845,6 +845,9 @@ void PerformEverySecond(void) } } + MqttPublishLoggingAsync(); + SyslogAsync(); + ResetGlobalValues(); if (Settings.tele_period) { diff --git a/tasmota/xdrv_01_webserver.ino b/tasmota/xdrv_01_webserver.ino index 7e74f2e89..6a76439b2 100644 --- a/tasmota/xdrv_01_webserver.ino +++ b/tasmota/xdrv_01_webserver.ino @@ -3028,8 +3028,10 @@ void HandleHttpCommand(void) do { char* tmp; size_t len; - GetLog(counter, &tmp, &len); - if (len) { + uint32_t loglevel = GetLog(counter, &tmp, &len); + if ((len > 0) && + (loglevel <= Settings.weblog_level) && + (TasmotaGlobal.masterlog_level <= Settings.weblog_level)) { // [14:49:36 MQTT: stat/wemos5/RESULT = {"POWER":"OFF"}] > [{"POWER":"OFF"}] char* JSON = (char*)memchr(tmp, '{', len); if (JSON) { // Is it a JSON message (and not only [15:26:08 MQT: stat/wemos5/POWER = O]) @@ -3105,8 +3107,10 @@ void HandleConsoleRefresh(void) do { char* tmp; size_t len; - GetLog(counter, &tmp, &len); - if (len) { + uint32_t loglevel = GetLog(counter, &tmp, &len); + if ((len > 0) && + (loglevel <= Settings.weblog_level) && + (TasmotaGlobal.masterlog_level <= Settings.weblog_level)) { if (len > sizeof(TasmotaGlobal.mqtt_data) -2) { len = sizeof(TasmotaGlobal.mqtt_data); } char stemp[len +1]; strlcpy(stemp, tmp, len); diff --git a/tasmota/xdrv_02_mqtt.ino b/tasmota/xdrv_02_mqtt.ino index 0a2caf760..f1e098eb1 100644 --- a/tasmota/xdrv_02_mqtt.ino +++ b/tasmota/xdrv_02_mqtt.ino @@ -291,18 +291,30 @@ void MqttUnsubscribe(const char *topic) MqttUnsubscribeLib(topic); } -void MqttPublishLogging(const char *mxtime) -{ - char saved_mqtt_data[strlen(TasmotaGlobal.mqtt_data) +1]; - memcpy(saved_mqtt_data, TasmotaGlobal.mqtt_data, sizeof(saved_mqtt_data)); +void MqttPublishLoggingAsync(void) { + static uint32_t counter = 1; -// ResponseTime_P(PSTR(",\"Log\":{\"%s\"}}"), TasmotaGlobal.log_data); // Will fail as some messages contain JSON - Response_P(PSTR("%s%s"), mxtime, TasmotaGlobal.log_data); // No JSON and ugly!! - char stopic[TOPSZ]; - GetTopic_P(stopic, STAT, TasmotaGlobal.mqtt_topic, PSTR("LOGGING")); - MqttPublishLib(stopic, false); + if (!Settings.flag.mqtt_enabled || // SetOption3 - Enable MQTT + !Settings.mqttlog_level || + (counter == TasmotaGlobal.web_log_index) || + TasmotaGlobal.global_state.mqtt_down) { return; } - memcpy(TasmotaGlobal.mqtt_data, saved_mqtt_data, sizeof(saved_mqtt_data)); + do { + char* tmp; + size_t len; + uint32_t loglevel = GetLog(counter, &tmp, &len); + if ((len > 0) && + (loglevel <= Settings.mqttlog_level) && + (TasmotaGlobal.masterlog_level <= Settings.mqttlog_level)) { + strlcpy(TasmotaGlobal.mqtt_data, tmp, len); // No JSON and ugly!! + char stopic[TOPSZ]; + GetTopic_P(stopic, STAT, TasmotaGlobal.mqtt_topic, PSTR("LOGGING")); + MqttPublishLib(stopic, false); + } + counter++; + counter &= 0xFF; + if (!counter) { counter++; } // Skip 0 as it is not allowed + } while (counter != TasmotaGlobal.web_log_index); } void MqttPublish(const char* topic, bool retained) diff --git a/tasmota/xdrv_40_telegram.ino b/tasmota/xdrv_40_telegram.ino index e959268d2..a810237b5 100644 --- a/tasmota/xdrv_40_telegram.ino +++ b/tasmota/xdrv_40_telegram.ino @@ -298,8 +298,10 @@ String TelegramExecuteCommand(const char *svalue) { do { char* tmp; size_t len; - GetLog(counter, &tmp, &len); - if (len) { + uint32_t loglevel = GetLog(counter, &tmp, &len); + if ((len > 0) && + (loglevel <= Settings.weblog_level) && + (TasmotaGlobal.masterlog_level <= Settings.weblog_level)) { // [14:49:36 MQTT: stat/wemos5/RESULT = {"POWER":"OFF"}] > [{"POWER":"OFF"}] char* JSON = (char*)memchr(tmp, '{', len); if (JSON) { // Is it a JSON message (and not only [15:26:08 MQT: stat/wemos5/POWER = O])