Skip to content

Commit

Permalink
event-log: Do a single Serial.write to get atomic output
Browse files Browse the repository at this point in the history 
Otherwise lines can interleave: AB\n\n instead of A\nB\n.
  • Loading branch information
@photron
photron committed Oct 21, 2024
1 parent 67ed598 commit f5eced5
Show file tree
Hide file tree
Showing 5 changed files with 63 additions and 61 deletions.
11 changes: 7 additions & 4 deletions software/src/config.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
Expand All @@ -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;
Expand All @@ -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);
}
}
}
Expand Down
8 changes: 5 additions & 3 deletions software/src/modules/debug/debug.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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);
}
Expand Down
98 changes: 47 additions & 51 deletions software/src/modules/event_log/event_log.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<std::mutex> 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()
Expand Down Expand Up @@ -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;
}

Expand All @@ -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;
}
Expand Down Expand Up @@ -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;
}
Expand All @@ -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
Expand All @@ -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<std::mutex> lock{trace_buf_mutex};
bool drop_line = trace_buf.free() < (len + 1 /* \n */);

trace_buf.push_n(buf, len);
std::lock_guard<std::mutex> 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;
Expand All @@ -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;
Expand Down Expand Up @@ -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;
Expand Down
4 changes: 2 additions & 2 deletions software/src/modules/event_log/event_log.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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, ...);

Expand All @@ -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, ...);

Expand Down
3 changes: 2 additions & 1 deletion software/src/modules/power_manager/power_manager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit f5eced5

Please sign in to comment.