neels has uploaded this change for review. ( https://gerrit.osmocom.org/c/libosmocore/+/35208?usp=email ) Change subject: logging: fix nul octets in log output / use osmo_strbuf ...................................................................... logging: fix nul octets in log output / use osmo_strbuf Patch [1] merged few weeks ago, for yet unknown reasons, sprinkles nul characters at seemingly randomly chosen log line ends. Trying to figure out why that happens, i got tired of the unreadable cruft, and decided to migrate the _output_buf() implementation to osmo_strbuf first. With osmo_strbuf in use and implementing 1:1 what the previous code did, the odd nul octets have disappeared. So the bug was caused by unreadable code. [1] 11a416827dd9f2da6b7c1db0e1e83adb1e6e5cc8 Ia7de9d88aa5ac48ec0d5c1a931a89d21c02c5433 "logging: ensure ANSI color escape is sent in same line/before newline" Related: OS#6284 Related: Ia7de9d88aa5ac48ec0d5c1a931a89d21c02c5433 Change-Id: Ib577a5e0d7450ce93ff21f37ba3262704cbf4752 --- M src/core/logging.c 1 file changed, 70 insertions(+), 84 deletions(-) git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/08/35208/1 diff --git a/src/core/logging.c b/src/core/logging.c index dc19cf3..0d215f4 100644 --- a/src/core/logging.c +++ b/src/core/logging.c @@ -486,18 +486,18 @@ unsigned int level, const char *file, int line, int cont, const char *format, va_list ap) { - int ret, len = 0, offset = 0, rem = buf_len; + int ret; const char *c_subsys = NULL; + struct osmo_strbuf sb = { .buf = buf, .len = buf_len }; + + /* safety net in case of encountering errors and returning nothing */ + buf[0] = '\0'; /* are we using color */ if (target->use_color) { c_subsys = color(subsys); - if (c_subsys) { - ret = snprintf(buf + offset, rem, "%s", c_subsys); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); - } + if (c_subsys) + OSMO_STRBUF_PRINTF(sb, "%s", c_subsys); } if (!cont) { if (target->print_ext_timestamp) { @@ -506,13 +506,10 @@ struct timeval tv; osmo_gettimeofday(&tv, NULL); localtime_r(&tv.tv_sec, &tm); - ret = snprintf(buf + offset, rem, "%04d%02d%02d%02d%02d%02d%03d ", - tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, - tm.tm_hour, tm.tm_min, tm.tm_sec, - (int)(tv.tv_usec / 1000)); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_PRINTF(sb, "%04d%02d%02d%02d%02d%02d%03d ", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, + tm.tm_hour, tm.tm_min, tm.tm_sec, + (int)(tv.tv_usec / 1000)); #endif } else if (target->print_timestamp) { time_t tm; @@ -520,97 +517,66 @@ goto err; /* Get human-readable representation of time. man ctime: we need at least 26 bytes in buf */ - if (rem < 26 || !ctime_r(&tm, buf + offset)) + if (OSMO_STRBUF_REMAIN(sb) < 26 || !ctime_r(&tm, sb.pos)) goto err; - ret = strlen(buf + offset); + ret = strnlen(sb.pos, 26); if (ret <= 0) goto err; + OSMO_STRBUF_ADDED_TAIL(sb, ret); /* Get rid of useless final '\n' added by ctime_r. We want a space instead. */ - buf[offset + ret - 1] = ' '; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_DROP_TAIL(sb, 1); + OSMO_STRBUF_PRINTF(sb, " "); } if (target->print_tid) { if (logging_tid == 0) logging_tid = (long int)osmo_gettid(); - ret = snprintf(buf + offset, rem, "%ld ", logging_tid); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_PRINTF(sb, "%ld ", logging_tid); } - if (target->print_category) { - ret = snprintf(buf + offset, rem, "%s%s%s%s ", - target->use_color ? level_color(level) : "", - log_category_name(subsys), - target->use_color ? OSMO_LOGCOLOR_END : "", - c_subsys ? c_subsys : ""); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); - } - if (target->print_level) { - ret = snprintf(buf + offset, rem, "%s%s%s%s ", - target->use_color ? level_color(level) : "", - log_level_str(level), - target->use_color ? OSMO_LOGCOLOR_END : "", - c_subsys ? c_subsys : ""); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); - } - if (target->print_category_hex) { - ret = snprintf(buf + offset, rem, "<%4.4x> ", subsys); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); - } + if (target->print_category) + OSMO_STRBUF_PRINTF(sb, "%s%s%s%s ", + target->use_color ? level_color(level) : "", + log_category_name(subsys), + target->use_color ? OSMO_LOGCOLOR_END : "", + c_subsys ? c_subsys : ""); + if (target->print_level) + OSMO_STRBUF_PRINTF(sb, "%s%s%s%s ", + target->use_color ? level_color(level) : "", + log_level_str(level), + target->use_color ? OSMO_LOGCOLOR_END : "", + c_subsys ? c_subsys : ""); + if (target->print_category_hex) + OSMO_STRBUF_PRINTF(sb, "<%4.4x> ", subsys); if (target->print_filename_pos == LOG_FILENAME_POS_HEADER_END) { switch (target->print_filename2) { case LOG_FILENAME_NONE: break; case LOG_FILENAME_PATH: - ret = snprintf(buf + offset, rem, "%s:%d ", file, line); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_PRINTF(sb, "%s:%d ", file, line); break; case LOG_FILENAME_BASENAME: - ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_PRINTF(sb, "%s:%d ", const_basename(file), line); break; } } } - ret = vsnprintf(buf + offset, rem, format, ap); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_APPEND(sb, vsnprintf, format, ap); /* For LOG_FILENAME_POS_LAST, print the source file info only when the caller ended the log * message in '\n'. If so, nip the last '\n' away, insert the source file info and re-append an * '\n'. All this to allow LOGP("start..."); LOGPC("...end\n") constructs. */ if (target->print_filename_pos == LOG_FILENAME_POS_LINE_END - && offset > 0 && buf[offset - 1] == '\n') { + && sb.pos > sb.buf && *(sb.pos - 1) == '\n') { switch (target->print_filename2) { case LOG_FILENAME_NONE: break; case LOG_FILENAME_PATH: - offset--; - len--; - ret = snprintf(buf + offset, rem, " (%s:%d)\n", file, line); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_DROP_TAIL(sb, 1); + OSMO_STRBUF_PRINTF(sb, " (%s:%d)\n", file, line); break; case LOG_FILENAME_BASENAME: - offset--; - len--; - ret = snprintf(buf + offset, rem, " (%s:%d)\n", const_basename(file), line); - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); + OSMO_STRBUF_DROP_TAIL(sb, 1); + OSMO_STRBUF_PRINTF(sb, " (%s:%d)\n", const_basename(file), line); break; } } @@ -618,21 +584,15 @@ if (target->use_color && c_subsys) { /* Ensure the last color escape is sent before the newline * (to not clobber journald, which works on single-lines only) */ - if (offset > 0 && buf[offset - 1] == '\n') { - offset--; rem++; - ret = snprintf(buf + offset, rem, OSMO_LOGCOLOR_END "\n"); + if (sb.pos > sb.buf && *(sb.pos - 1) == '\n') { + OSMO_STRBUF_DROP_TAIL(sb, 1); + OSMO_STRBUF_PRINTF(sb, OSMO_LOGCOLOR_END "\n"); } else { - ret = snprintf(buf + offset, rem, OSMO_LOGCOLOR_END); + OSMO_STRBUF_PRINTF(sb, OSMO_LOGCOLOR_END); } - - if (ret < 0) - goto err; - OSMO_SNPRINTF_RET(ret, rem, offset, len); } err: - len = OSMO_MIN(buf_len - 1, len); - buf[len] = '\0'; - return len; + return OSMO_STRBUF_CHAR_COUNT(sb); } /* Format the log line for given target; use a stack buffer and call target->output */ -- To view, visit https://gerrit.osmocom.org/c/libosmocore/+/35208?usp=email To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: libosmocore Gerrit-Branch: master Gerrit-Change-Id: Ib577a5e0d7450ce93ff21f37ba3262704cbf4752 Gerrit-Change-Number: 35208 Gerrit-PatchSet: 1 Gerrit-Owner: neels &lt;nhofmeyr(a)sysmocom.de&gt; Gerrit-MessageType: newchange