From f5eced55390e5d18d5cc6e7b57c897c0fdc8ab0b Mon Sep 17 00:00:00 2001 From: Matthias Bolte Date: Mon, 21 Oct 2024 17:14:04 +0200 Subject: [PATCH] event-log: Do a single Serial.write to get atomic output Otherwise lines can interleave: AB\n\n instead of A\nB\n. --- software/src/config.cpp | 11 ++- software/src/modules/debug/debug.cpp | 8 +- software/src/modules/event_log/event_log.cpp | 98 +++++++++---------- software/src/modules/event_log/event_log.h | 4 +- .../modules/power_manager/power_manager.cpp | 3 +- 5 files changed, 63 insertions(+), 61 deletions(-) diff --git a/software/src/config.cpp b/software/src/config.cpp index 56232fb4d..9f8d21bf0 100644 --- a/software/src/config.cpp +++ b/software/src/config.cpp @@ -668,7 +668,8 @@ void Config::save_to_file(File &file) logger.printfln("JSON doc overflow while writing file %s! Doc capacity is %u. Truncated doc follows.", file.name(), capacity); String str; serializeJson(doc, str); - logger.println_plain(str.c_str(), str.length()); + str += "\n"; + logger.print_plain(str.c_str(), str.length()); } } serializeJson(doc, file); @@ -691,7 +692,8 @@ void Config::write_to_stream_except(Print &output, const char *const *keys_to_ce logger.printfln("JSON doc overflow while writing to stream! Doc capacity is %u. Truncated doc follows.", capacity); String str; serializeJson(doc, str); - logger.println_plain(str.c_str(), str.length()); + str += "\n"; + logger.print_plain(str.c_str(), str.length()); } } serializeJson(doc, output); @@ -716,7 +718,7 @@ String Config::to_string_except(const char *const *keys_to_censor, size_t keys_t logger.printfln("JSON doc overflow while converting to string! Doc capacity is zero but needed %u.", json_size(false)); } else { logger.printfln("JSON doc overflow while converting to string! Doc capacity is %u. Truncated doc follows.", capacity); - logger.println_plain(result.c_str(), result.length()); + logger.print_plain((result + "\n").c_str(), result.length() + 1); } } return result; @@ -736,7 +738,8 @@ void Config::to_string_except(const char *const *keys_to_censor, size_t keys_to_ logger.printfln("JSON doc overflow while converting to string! Doc capacity is zero but needed %u.", json_size(false)); } else { logger.printfln("JSON doc overflow while converting to string! Doc capacity is %u. Truncated doc follows.", capacity); - logger.println_plain(ptr, written); + logger.print_plain(ptr, written); + logger.print_plain("\n", 1); } } } diff --git a/software/src/modules/debug/debug.cpp b/software/src/modules/debug/debug.cpp index b8e63031d..89bea37f1 100644 --- a/software/src/modules/debug/debug.cpp +++ b/software/src/modules/debug/debug.cpp @@ -54,7 +54,8 @@ static void malloc_failed_log_detailed(size_t size, uint32_t caps, const char *f size_t backtrace_len = strn_backtrace(backtrace_buf, sizeof(backtrace_buf), 1); logger.printfln("malloc_failed_hook sz=%u frBl=%u frTot=%u caps=0x%x fn=%s t=%s", size, ram_info.largest_free_block, ram_info.total_free_bytes, caps, function_name, task_name); - logger.println_plain(backtrace_buf, backtrace_len); + logger.print_plain(backtrace_buf, backtrace_len); + logger.print_plain("\n", 1); } // Called on affected task's stack, which might be small. @@ -66,8 +67,9 @@ static void malloc_failed_hook(size_t size, uint32_t caps, const char *function_ malloc_failed_log_detailed(size, caps, function_name, task_name); } else { logger.print_timestamp(); - logger.println_plain("malloc_failed_hook from other task", 34); - logger.println_plain(task_name, strlen(task_name)); + logger.print_plain("malloc_failed_hook from other task\n", 35); + logger.print_plain(task_name, strlen(task_name)); + logger.print_plain("\n", 1); esp_backtrace_print(INT32_MAX); } diff --git a/software/src/modules/event_log/event_log.cpp b/software/src/modules/event_log/event_log.cpp index 5a763ff75..e0617aac6 100644 --- a/software/src/modules/event_log/event_log.cpp +++ b/software/src/modules/event_log/event_log.cpp @@ -176,48 +176,35 @@ void EventLog::print_drop(size_t count) event_buf.pop(&c); } - while (event_buf.used() > 0 && c != '\n'){ + while (event_buf.used() > 0 && c != '\n') { event_buf.pop(&c); } } void EventLog::print_timestamp() { - char buf[EVENT_LOG_TIMESTAMP_LENGTH + 1 /* \0 */]; + char buf[EVENT_LOG_TIMESTAMP_LENGTH + 1 /* \n | \0 */]; format_timestamp(buf); - println_plain(buf, EVENT_LOG_TIMESTAMP_LENGTH); + buf[EVENT_LOG_TIMESTAMP_LENGTH] = '\n'; + + print_plain(buf, EVENT_LOG_TIMESTAMP_LENGTH + 1); } -size_t EventLog::println_plain(const char *buf, size_t len) +size_t EventLog::print_plain(const char *buf, size_t len) { - // Strip away \r\n. We only use \n as line endings for the serial - // output as well as the event log. Removing \r\n by reducing the length - // works, because if a message does not end in \n we add the \n below. - if (len >= 2 && buf[len - 2] == '\r' && buf[len - 1] == '\n') { - len -= 2; - } - Serial.write(buf, len); - if (buf[len - 1] != '\n') { - Serial.println(""); - } - { std::lock_guard lock{event_buf_mutex}; - if (event_buf.free() < len + 1 /* \n */) { - print_drop(len + 1 /* \n */ - event_buf.free()); + if (event_buf.free() < len) { + print_drop(len - event_buf.free()); } for (size_t i = 0; i < len; ++i) { event_buf.push(buf[i]); } - - if (buf[len - 1] != '\n') { - event_buf.push('\n'); - } } #if MODULE_WS_AVAILABLE() @@ -246,10 +233,6 @@ size_t EventLog::println_plain(const char *buf, size_t len) } #endif - if (buf[len - 1] != '\n') { - return len + 1; - } - return len; } @@ -266,7 +249,13 @@ size_t EventLog::vprintfln_plain(const char *fmt, va_list args) written = buf_len - 1; // Don't include termination, which vsnprintf always leaves in. } - println_plain(buf, written); + // The IDF might log messages ending with "\r\n" via tf_event_log_[v]printfln + if (written >= 2 && buf[written - 2] == '\r' && buf[written - 1] == '\n') { + written -= 2; + } + + buf[written++] = '\n'; // At this point written < buf_len is guaranteed + print_plain(buf, written); return written; } @@ -296,7 +285,13 @@ size_t EventLog::vprintfln_prefixed(const char *prefix, size_t prefix_len, const written = buf_len - 1; // Don't include termination, which vsnprintf always leaves in } - println_plain(buf, written); + // The IDF might log messages ending with "\r\n" via tf_event_log_[v]printfln + if (written >= 2 && buf[written - 2] == '\r' && buf[written - 1] == '\n') { + written -= 2; + } + + buf[written++] = '\n'; // At this point written < buf_len is guaranteed + print_plain(buf, written); return written; } @@ -322,7 +317,7 @@ void EventLog::trace_drop(size_t count) trace_buf.pop(&c); } - while (trace_buf.used() > 0 && c != '\n'){ + while (trace_buf.used() > 0 && c != '\n') { trace_buf.pop(&c); } #else @@ -333,36 +328,25 @@ void EventLog::trace_drop(size_t count) void EventLog::trace_timestamp() { #if defined(BOARD_HAS_PSRAM) - char buf[EVENT_LOG_TIMESTAMP_LENGTH + 1 /* \0 */]; + char buf[EVENT_LOG_TIMESTAMP_LENGTH + 1 /* \n | \0 */]; format_timestamp(buf); - traceln_plain(buf, EVENT_LOG_TIMESTAMP_LENGTH); + buf[EVENT_LOG_TIMESTAMP_LENGTH] = '\n'; + + trace_plain(buf, EVENT_LOG_TIMESTAMP_LENGTH + 1); #endif } -size_t EventLog::traceln_plain(const char *buf, size_t len) +size_t EventLog::trace_plain(const char *buf, size_t len) { #if defined(BOARD_HAS_PSRAM) - // Strip away \r\n. We only use \n as line endings for the serial - // output as well as the event log. Removing \r\n by reducing the length - // works, because if a message does not end in \n we add the \n below. - if (len >= 2 && buf[len - 2] == '\r' && buf[len - 1] == '\n') { - len -= 2; - } - - { - std::lock_guard lock{trace_buf_mutex}; - bool drop_line = trace_buf.free() < (len + 1 /* \n */); - - trace_buf.push_n(buf, len); + std::lock_guard lock{trace_buf_mutex}; + bool drop_line = trace_buf.free() < len; - if (buf[len - 1] != '\n') { - trace_buf.push('\n'); - } + trace_buf.push_n(buf, len); - if (drop_line) { - trace_buf.pop_until('\n'); - } + if (drop_line) { + trace_buf.pop_until('\n'); } return len; @@ -388,7 +372,13 @@ size_t EventLog::vtracefln_plain(const char *fmt, va_list args) written = buf_len - 1; // Don't include termination, which vsnprintf always leaves in } - traceln_plain(buf, written); + // The IDF might log messages ending with "\r\n" via tf_event_log_[v]printfln + if (written >= 2 && buf[written - 2] == '\r' && buf[written - 1] == '\n') { + written -= 2; + } + + buf[written++] = '\n'; // At this point written < buf_len is guaranteed + trace_plain(buf, written); #endif return written; @@ -422,7 +412,13 @@ size_t EventLog::vtracefln_prefixed(const char *prefix, size_t prefix_len, const written = buf_len - 1; // Don't include termination, which vsnprintf always leaves in. } - traceln_plain(buf, written); + // The IDF might log messages ending with "\r\n" via tf_event_log_[v]printfln + if (written >= 2 && buf[written - 2] == '\r' && buf[written - 1] == '\n') { + written -= 2; + } + + buf[written++] = '\n'; // At this point written < buf_len is guaranteed + trace_plain(buf, written); #endif return written; diff --git a/software/src/modules/event_log/event_log.h b/software/src/modules/event_log/event_log.h index 36a72c774..d2a019534 100644 --- a/software/src/modules/event_log/event_log.h +++ b/software/src/modules/event_log/event_log.h @@ -48,8 +48,8 @@ class EventLog final : public IModule void print_drop(size_t count); void print_timestamp(); + size_t print_plain(const char *buf, size_t len); - size_t println_plain(const char *buf, size_t len); size_t vprintfln_plain(const char *fmt, va_list args); [[gnu::format(__printf__, 2, 3)]] size_t printfln_plain(const char *fmt, ...); @@ -58,8 +58,8 @@ class EventLog final : public IModule void trace_drop(size_t count); void trace_timestamp(); + size_t trace_plain(const char *buf, size_t len); - size_t traceln_plain(const char *buf, size_t len); size_t vtracefln_plain(const char *fmt, va_list args); [[gnu::format(__printf__, 2, 3)]] size_t tracefln_plain(const char *fmt, ...); diff --git a/software/src/modules/power_manager/power_manager.cpp b/software/src/modules/power_manager/power_manager.cpp index be2406b48..84a726aa3 100644 --- a/software/src/modules/power_manager/power_manager.cpp +++ b/software/src/modules/power_manager/power_manager.cpp @@ -1118,7 +1118,8 @@ void PowerManager::update_energy() } #if ENABLE_PM_TRACE - logger.traceln_plain(trace_log, trace_log_len); + trace_log_len += snprintf_u(trace_log + trace_log_len, sizeof(trace_log) - trace_log_len, "\n"); + logger.trace_plain(trace_log, trace_log_len); #endif // Calculate long-term minimum over one-minute blocks