From c09588c95a72429641d2c10225001f0f32148bfe Mon Sep 17 00:00:00 2001 From: Ben Gray Date: Thu, 2 Apr 2026 13:33:22 +0100 Subject: [PATCH 1/5] DELIA-70109: Updates to ethanlog client library Updated the logging library to support log line wrapping and also queuing of messages if the pipe is full. Both options are disabled by default, but can be enabled via environment variables. --- plugins/EthanLog/client/lib/source/ethanlog.c | 259 -------- .../EthanLog/client/lib/source/ethanlog.cpp | 595 ++++++++++++++++++ plugins/EthanLog/source/EthanLogLoop.cpp | 2 +- 3 files changed, 596 insertions(+), 260 deletions(-) delete mode 100644 plugins/EthanLog/client/lib/source/ethanlog.c create mode 100644 plugins/EthanLog/client/lib/source/ethanlog.cpp diff --git a/plugins/EthanLog/client/lib/source/ethanlog.c b/plugins/EthanLog/client/lib/source/ethanlog.c deleted file mode 100644 index 4994f17a..00000000 --- a/plugins/EthanLog/client/lib/source/ethanlog.c +++ /dev/null @@ -1,259 +0,0 @@ -/* -* If not stated otherwise in this file or this component's LICENSE file the -* following copyright and licenses apply: -* -* Copyright 2020 Sky UK -* -* Licensed under the Apache License, Version 2.0 (the "License"); -* you may not use this file except in compliance with the License. -* You may obtain a copy of the License at -* -* http://www.apache.org/licenses/LICENSE-2.0 -* -* Unless required by applicable law or agreed to in writing, software -* distributed under the License is distributed on an "AS IS" BASIS, -* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -* See the License for the specific language governing permissions and -* limitations under the License. -*/ - -#include "ethanlog.h" - -#include -#include -#include -#include -#include -#include -#include -#include -#include - -#define ELOG_RECORD_DELIM '\x1e' -#define ELOG_FIELD_DELIM '\x1f' - -#define ELOG_MAX_LOG_MSG_LENGTH 512UL -#define ELOG_MAX_FUNC_NAME_LENGTH ((int)128) -#define ELOG_MAX_FILE_NAME_LENGTH ((int)64) - - -#define ELOG_MIN(a,b) (((a) < (b)) ? (a) : (b)) - -#define ELOG_PIPE_UNINITIALIZED -1 -#define ELOG_PIPE_ERROR -2 -#define ELOG_PIPE_REDIRECT_CONSOLE -3 - -static int _ethanlog_pipefd = ELOG_PIPE_UNINITIALIZED; - - -static int ethanlog_init(void) -{ - const char* env; - int pipe_fd; - - env = getenv("ETHAN_LOGGING_TO_CONSOLE"); - if ((env != NULL) && (env[0] == '1') && (env[1] == '\0')) { - return ELOG_PIPE_REDIRECT_CONSOLE; - } - - /* the following environment variable is set by the hypervisor, it - * tells us the number of open file descriptor to use for logging. - */ - env = getenv("ETHAN_LOGGING_PIPE"); - if (env == NULL) { - return ELOG_PIPE_ERROR; - } - - pipe_fd = atoi(env); - if ((pipe_fd < 3) || (pipe_fd > 2048)) { - return ELOG_PIPE_ERROR; - } - - return pipe_fd; -} - -static int ethanlog_console(int level, const char *filename, const char *function, int line, - const char *format, va_list ap) -{ - int n = 0; - struct iovec iov[6]; - char tbuf[32]; - char fbuf[ELOG_MAX_FILE_NAME_LENGTH + ELOG_MAX_FUNC_NAME_LENGTH + 32]; - char mbuf[ELOG_MAX_LOG_MSG_LENGTH]; - int len; - struct timespec ts; - - clock_gettime(CLOCK_MONOTONIC, &ts); - - iov[n].iov_base = tbuf; - iov[n].iov_len = snprintf(tbuf, sizeof(tbuf), "%.010lu.%.06lu ", - ts.tv_sec, ts.tv_nsec / 1000); - iov[n].iov_len = ELOG_MIN(iov[n].iov_len, sizeof(tbuf)); - n++; - - switch (level) { - case ETHAN_LOG_FATAL: - iov[n].iov_base = (void*)"FTL: "; - iov[n].iov_len = 5; - break; - case ETHAN_LOG_ERROR: - iov[n].iov_base = (void*)"ERR: "; - iov[n].iov_len = 5; - break; - case ETHAN_LOG_WARNING: - iov[n].iov_base = (void*)"WRN: "; - iov[n].iov_len = 5; - break; - case ETHAN_LOG_MILESTONE: - iov[n].iov_base = (void*)"MIL: "; - iov[n].iov_len = 5; - break; - case ETHAN_LOG_INFO: - iov[n].iov_base = (void*)"NFO: "; - iov[n].iov_len = 5; - break; - case ETHAN_LOG_DEBUG: - iov[n].iov_base = (void*)"DBG: "; - iov[n].iov_len = 5; - break; - default: - iov[n].iov_base = (void*)": "; - iov[n].iov_len = 2; - break; - } - n++; - - len = snprintf(fbuf, sizeof(fbuf), "< S:%.*s F:%.*s L:%d > ", - ELOG_MAX_FILE_NAME_LENGTH, filename ?: "?", - ELOG_MAX_FUNC_NAME_LENGTH, function ?: "?", - line); - if (len > 0 ) { - iov[n].iov_base = (void *) fbuf; - iov[n].iov_len = ELOG_MIN(len, sizeof(fbuf)); - n++; - } - - len = vsnprintf(mbuf, sizeof(mbuf), format, ap); - if (len > 0) { - iov[n].iov_base = (void *) mbuf; - iov[n].iov_len = ELOG_MIN(len, sizeof(mbuf)); - n++; - } - - iov[n].iov_base = (void*)"\n"; - iov[n].iov_len = 1; - n++; - - if (level <= ETHAN_LOG_WARNING) { - return TEMP_FAILURE_RETRY(writev(STDERR_FILENO, iov, n)); - } else { - return TEMP_FAILURE_RETRY(writev(STDOUT_FILENO, iov, n)); - } -} - -int ethanlog_vprint(int level, const char *filename, const char *function, int line, - const char *format, va_list ap) -{ - struct timespec ts; - char buf[ELOG_MAX_LOG_MSG_LENGTH]; - char *p, *end; - char *basename; - int len; - - /* run the sanity checks first */ - if ((level < ETHAN_LOG_FATAL) || (level > ETHAN_LOG_MILESTONE)) { - errno = EINVAL; - return -1; - } - - /* initialise the pipe if we haven't already */ - if (__builtin_expect((_ethanlog_pipefd == ELOG_PIPE_UNINITIALIZED), 0)) { - _ethanlog_pipefd = ethanlog_init(); - } - - /* check managed to initialise the pipe */ - if (__builtin_expect((_ethanlog_pipefd == ELOG_PIPE_ERROR), 0)) { - errno = EPIPE; - return -1; - } - - /* check if environment variable is set to redirect stderr/stdout */ - if (_ethanlog_pipefd == ELOG_PIPE_REDIRECT_CONSOLE) { - return ethanlog_console(level, filename, function, line, format, ap); - } - - - p = buf; - end = buf + ELOG_MAX_LOG_MSG_LENGTH; - - - *p++ = ELOG_RECORD_DELIM; - - /* level field */ - *p++ = ELOG_FIELD_DELIM; - *p++ = 'L'; - *p++ = '0' + level; - - /* timestamp */ - if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) - ts.tv_sec = ts.tv_nsec = 0; - p += sprintf(p, "%cT%08lx.%08lx", ELOG_FIELD_DELIM, ts.tv_sec, ts.tv_nsec); - - /* source file basename (limited to 64 characters) */ - if (filename) { - *p++ = ELOG_FIELD_DELIM; - if ((basename = strrchr(filename, '/')) != NULL) - filename = (basename + 1); - p += sprintf(p, "S%.*s", ELOG_MAX_FILE_NAME_LENGTH, filename); - } - - /* function (limited to 128 characters) */ - if (function) { - *p++ = ELOG_FIELD_DELIM; - p += sprintf(p, "F%.*s", ELOG_MAX_FUNC_NAME_LENGTH, function); - } - - /* line number */ - if (line > 0) { - *p++ = ELOG_FIELD_DELIM; - p += sprintf(p, "N%d", line); - } - - - /* process id */ - *p++ = ELOG_FIELD_DELIM; - p += sprintf(p, "P%x", getpid()); - - - /* apply the message, limit it to the buffer size */ - *p++ = ELOG_FIELD_DELIM; - *p++ = 'M'; - if (format) { - len = vsnprintf(p, (end - p) - 1, format, ap); - p += ELOG_MIN(len, ((end - p) - 1)); - } - - /* set the terminator and we're done */ - *p++ = ELOG_RECORD_DELIM; - - - /* finally we need to send the message */ - return TEMP_FAILURE_RETRY(write(_ethanlog_pipefd, buf, (p - buf))); -} - -void vethanlog(int level, const char *filename, const char *function, - int line, const char *format, va_list ap) -{ - ethanlog_vprint(level, filename, function, line, format, ap); -} - -void ethanlog(int level, const char *filename, const char *function, int line, - const char *format, ...) -{ - va_list vl; - - va_start(vl, format); - ethanlog_vprint(level, filename, function, line, format, vl); - va_end(vl); -} - diff --git a/plugins/EthanLog/client/lib/source/ethanlog.cpp b/plugins/EthanLog/client/lib/source/ethanlog.cpp new file mode 100644 index 00000000..8c514b84 --- /dev/null +++ b/plugins/EthanLog/client/lib/source/ethanlog.cpp @@ -0,0 +1,595 @@ +/* + * If not stated otherwise in this file or this component's LICENSE file the + * following copyright and licenses apply: + * + * Copyright 2026 Sky UK + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "ethanlog.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include + + +static constexpr char ETHANLOG_RECORD_DELIM = '\x1e'; +static constexpr char ETHANLOG_FIELD_DELIM = '\x1f'; + +static constexpr char ETHANLOG_WRAP_INDICATOR[] = "\xe2\x86\xb5"; // '↵' character + +static constexpr size_t ETHANLOG_MAX_LOG_MSG_LENGTH = 512; +static constexpr int ETHANLOG_MAX_FUNC_NAME_LENGTH = 128; +static constexpr int ETHANLOG_MAX_FILE_NAME_LENGTH = 64; +static constexpr size_t ETHANLOG_MAX_WRAP_INDICATOR_LEN = 32; + +static constexpr int ETHANLOG_PIPE_UNINITIALIZED = -1; +static constexpr int ETHANLOG_PIPE_REDIRECT_CONSOLE = -2; +static constexpr int ETHANLOG_PIPE_ERROR = -3; + +static constexpr char ETHANLOG_LEVEL_FATAL_CHAR = '1'; +static constexpr char ETHANLOG_LEVEL_ERROR_CHAR = '2'; +static constexpr char ETHANLOG_LEVEL_WARNING_CHAR = '3'; +static constexpr char ETHANLOG_LEVEL_INFO_CHAR = '4'; +static constexpr char ETHANLOG_LEVEL_DEBUG_CHAR = '5'; +static constexpr char ETHANLOG_LEVEL_MILESTONE_CHAR = '6'; + +static_assert(ETHANLOG_MAX_LOG_MSG_LENGTH > + (64 + ETHANLOG_MAX_FUNC_NAME_LENGTH + ETHANLOG_MAX_FILE_NAME_LENGTH + ETHANLOG_MAX_WRAP_INDICATOR_LEN), + "Max log message length must be large enough to hold the max size of all fields"); + +static std::atomic gEthanlogPipefd = ETHANLOG_PIPE_UNINITIALIZED; + +// The number of log messages to allow in a burst before we start dropping messages, this is +// used to prevent a flood of log messages from overwhelming the logging system and causing +static size_t gEthanLogMaxQueuedMessages = 0; + +// Log wrapping is disabled by default, it can be enabled by setting the +// ETHAN_LOGGING_ENABLE_WRAP environment variable to "1". +static std::atomic gEthanLogWrapEnabled = false; + +// The wrap indicator is the set of characters to append to the end of a +// log message when it is too long and has been truncated. +static char gEthanLogWrapIndicator[ETHANLOG_MAX_WRAP_INDICATOR_LEN + 1] = { 0 }; +static int gEthanLogWrapIndicatorLen = 0; + + +static size_t ethanlogPopulateMsgPrefix(int level, const char *filename, + const char *function, int line, + char* const buf); + +// ----------------------------------------------------------------------------- +/** + * @brief Initialises the logging system, this is called on the first call to + * log a message and initialises the pipe file descriptor to write log messages + * to. + * + * This is also checks some environment variables to determine if log messages + * should be written to the console instead of the pipe, and also to determine + * if log line wrapping should be enabled and what the wrap indicator should be. + * + */ +static void ethanLogInit() +{ + const char *env = getenv("ETHAN_LOGGING_TO_CONSOLE"); + if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) + { + gEthanlogPipefd = ETHANLOG_PIPE_REDIRECT_CONSOLE; + return; + } + + // check if log line wrapping should be enabled + env = getenv("ETHAN_LOGGING_ENABLE_WRAP"); + if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) + { + gEthanLogWrapEnabled = true; + } + + if (gEthanLogWrapEnabled) + { + // check if a custom log wrapping indicator is set, if not use the default + env = getenv("ETHAN_LOGGING_WRAP_INDICATOR"); + if ((env != nullptr) && (env[0] != '\0')) + { + strncpy(gEthanLogWrapIndicator, env, ETHANLOG_MAX_WRAP_INDICATOR_LEN); + gEthanLogWrapIndicator[ETHANLOG_MAX_WRAP_INDICATOR_LEN] = '\0'; + } + else + { + strcpy(gEthanLogWrapIndicator, ETHANLOG_WRAP_INDICATOR); + } + gEthanLogWrapIndicatorLen = strlen(gEthanLogWrapIndicator); + } + + // check if want to enable the log message queue + env = getenv("ETHAN_LOGGING_QUEUE_SIZE"); + if (env != nullptr) + { + int queueSize = atoi(env); + if (queueSize > 0) + { + gEthanLogMaxQueuedMessages = std::max(queueSize, 512UL); + } + } + + // the following environment variable is set by the hypervisor, it + // tells us the number of open file descriptor to use for logging. + env = getenv("ETHAN_LOGGING_PIPE"); + if (env == nullptr) + { + gEthanlogPipefd = ETHANLOG_PIPE_ERROR; + return; + } + + // the actual pipe fd + int pipeFd = atoi(env); + if ((pipeFd < 3) || (pipeFd > 2048)) + { + gEthanlogPipefd = ETHANLOG_PIPE_ERROR; + } + else + { + gEthanlogPipefd = pipeFd; + } +} + +// ----------------------------------------------------------------------------- +/** + * @brief Simple logging function that writes the log message to the console. + * + * This function is used if ETHAN_LOGGING_TO_CONSOLE=1 i set in the console. + * + */ +static int ethanlogToConsole(int level, const char *filename, const char *function, + int line, const char *format, va_list ap) +{ + char tbuf[32]; + timespec ts = { }; + clock_gettime(CLOCK_MONOTONIC, &ts); + snprintf(tbuf, sizeof(tbuf), "%.010lu.%.06lu", ts.tv_sec, ts.tv_nsec / 1000); + + const char *prefix; + switch (level) + { + case ETHAN_LOG_FATAL: + prefix = "FTL"; + break; + case ETHAN_LOG_ERROR: + prefix = "ERR"; + break; + case ETHAN_LOG_WARNING: + prefix = "WRN"; + break; + case ETHAN_LOG_MILESTONE: + prefix = "MIL"; + break; + case ETHAN_LOG_INFO: + prefix = "NFO"; + break; + case ETHAN_LOG_DEBUG: + prefix = "DBG"; + break; + default: + prefix = " "; + break; + } + + char mbuf[2048]; + vsnprintf(mbuf, sizeof(mbuf), format, ap); + + const int stream = (level <= ETHAN_LOG_WARNING) ? STDERR_FILENO : STDOUT_FILENO; + return dprintf(stream, "%s %s: < S:%s F:%s L:%d > %s\n", + tbuf, prefix, filename ?: "?", function ?: "?", line, mbuf); +} + +// ----------------------------------------------------------------------------- +/** + * @brief + * + */ +static bool ethanlogWriteToPipe(const char* buf, size_t len) +{ + const int fd = gEthanlogPipefd; + if (fd < 0) + { + errno = EBADF; + return false; + } + + ssize_t written = TEMP_FAILURE_RETRY(write(fd, buf, len)); + if (written != static_cast(len)) + { + if ((errno == EWOULDBLOCK) || (errno == EAGAIN)) + { + // The pipe is blocked, we will handle this in the caller by queuing the message + return false; + } + else + { + // If we fail to write to the pipe, we mark it as an error and drop future messages. + gEthanlogPipefd = ETHANLOG_PIPE_ERROR; + return false; + } + } + + return true; +} + +// ----------------------------------------------------------------------------- +/** + * @brief Helper function to create a log message indicating that messages have + * been dropped due to backpressure on the pipe. + * + */ +static std::string ethanlogCreateDroppedMessage(int count) +{ + char buf[ETHANLOG_MAX_LOG_MSG_LENGTH]; + const size_t prefixLen = + ethanlogPopulateMsgPrefix(ETHAN_LOG_WARNING, nullptr, nullptr, -1, buf); + + int msgLen = snprintf(buf + prefixLen, sizeof(buf) - prefixLen - 1, + "Dropped %d log messages due to backpressure", count); + msgLen = std::min(msgLen, (ETHANLOG_MAX_LOG_MSG_LENGTH - prefixLen - 2)); + + buf[prefixLen + msgLen] = ETHANLOG_RECORD_DELIM; + + return std::string(buf, prefixLen + msgLen + 1); +} + +// ----------------------------------------------------------------------------- +/** + * @brief Helper function to create a log message indicating that messages have + * been dropped due to backpressure on the pipe. + * + */ +static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) +{ + static std::atomic droppedMessages = 0; + + static std::mutex queueMessageLock; + static std::deque queuedMessages; + static std::atomic queuedMessageCount = 0; + + // First check if we have queued messages, if we do then we need to write + // those out before writing the new message, to ensure messages are written + // in order (although this is not guaranteed if another thread is writing + // messages at the same time, but it is better than always writing messages + // out of order). + if (queuedMessageCount > 0) + { + std::lock_guard locker(queueMessageLock); + + while (!queuedMessages.empty()) + { + const auto &msg = queuedMessages.front(); + if (ethanlogWriteToPipe(msg.data(), msg.size())) + { + queuedMessages.pop_front(); + queuedMessageCount--; + } + else + { + break; + } + } + + const size_t availableQueueSpace = gEthanLogMaxQueuedMessages - queuedMessages.size(); + const size_t requiredQueueSpace = (droppedMessages > 0) ? 2 : 1; + + // If we still have messages in the queue, then either queue up the new + // message or drop it if we've reached the maximum queue size, to prevent + // unbounded memory growth. + if (availableQueueSpace < requiredQueueSpace) + { + droppedMessages++; + errno = EWOULDBLOCK; + return -1; + } + + // If the queue is not empty then just add the new message to the end of + // the queue, and we're done. + if (!queuedMessages.empty()) + { + // Add "dropped messages" message if needed before the new message, + // to ensure it is logged before any new messages in the queue + // (already checked for space in the queue above). + if (droppedMessages > 0) + { + const auto msg = ethanlogCreateDroppedMessage(droppedMessages); + queuedMessages.emplace_back(msg); + queuedMessageCount++; + droppedMessages = 0; + } + + // Also queue the new message + queuedMessages.emplace_back(buf, len); + queuedMessageCount++; + return 0; + } + + // If we have dropped messages but the queue is now empty, then we can try + // writing the dropped message directly to the pipe, if that fails then we + // will add it to the queue and add the new message to the queue as well. + if (droppedMessages > 0) + { + const auto msg = ethanlogCreateDroppedMessage(droppedMessages); + if (ethanlogWriteToPipe(msg.data(), msg.size()) == false) + { + queuedMessages.emplace_back(msg); + queuedMessageCount++; + } + + droppedMessages = 0; + } + } + + // At this point we've successfully written all queued messages, however + // the pipe _may_ still be blocked on this write, or another thread may come + // in and filled the pipe and the queued messages again. So we try and write, + // if fails then we try and queue the message again (which may fail if another + // thread has filled the queue in the meantime). + if (ethanlogWriteToPipe(buf, len) == false) + { + std::lock_guard locker(queueMessageLock); + + if (queuedMessages.size() < gEthanLogMaxQueuedMessages) + { + queuedMessages.emplace_back(buf, len); + queuedMessageCount++; + return 0; + } + + droppedMessages++; + errno = EWOULDBLOCK; + return -1; + } + + return 0; +} + +// ----------------------------------------------------------------------------- +/** + * @brief Attempts to write the given log message to the pipe, if the pipe is + * blocked then the message may be queued if queueing is enabled, otherwise the + * message will be dropped. + * + * + */ +static int ethanlogWriteMessage(const char* buf, size_t len) +{ + const int fd = gEthanlogPipefd; + if (fd < 0) + { + errno = EBADF; + return -1; + } + + if (gEthanLogMaxQueuedMessages > 0) + return ethanlogWriteMessageWithQueuing(buf, len); + + if (!ethanlogWriteToPipe(buf, len)) + return -1; + else + return 0; +} + +// ----------------------------------------------------------------------------- +/** + * @brief Populates a log line prefix with the given log level, filename, + * function name and line number, + * + * The end result is the \a buf filled with the prefix up to the 'M' field, and + * the return value is the length of the prefix in bytes. The caller can then + * append the log message after the prefix, and then add the record delimiter at + * the end before writing the message to the pipe. + * + */ +static size_t ethanlogPopulateMsgPrefix(int level, const char *filename, + const char *function, int line, + char* const buf) +{ + char* p = buf; + + *p++ = ETHANLOG_RECORD_DELIM; + + // Log level + *p++ = ETHANLOG_FIELD_DELIM; + *p++ = 'L'; + switch (level) + { + case ETHAN_LOG_DEBUG: + *p++ = ETHANLOG_LEVEL_DEBUG_CHAR; + break; + case ETHAN_LOG_INFO: + *p++ = ETHANLOG_LEVEL_INFO_CHAR; + break; + case ETHAN_LOG_MILESTONE: + *p++ = ETHANLOG_LEVEL_MILESTONE_CHAR; + break; + case ETHAN_LOG_WARNING: + *p++ = ETHANLOG_LEVEL_WARNING_CHAR; + break; + case ETHAN_LOG_ERROR: + *p++ = ETHANLOG_LEVEL_ERROR_CHAR; + break; + case ETHAN_LOG_FATAL: + *p++ = ETHANLOG_LEVEL_FATAL_CHAR; + break; + default: + *p++ = ETHANLOG_LEVEL_INFO_CHAR; + } + + // gcc complains about the use of sprintf, but all writes in this code are carefully bounds checked to ensure we + // don't overflow the buffer, so we can safely ignore these warnings. +#pragma GCC diagnostic push +#pragma GCC diagnostic ignored "-Wdeprecated-declarations" + + // Timestamp for the log + timespec ts = {.tv_sec = 0, .tv_nsec = 0}; + if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) + ts.tv_sec = ts.tv_nsec = 0; + p += sprintf(p, "%cT%08lx.%08lx", ETHANLOG_FIELD_DELIM, ts.tv_sec, ts.tv_nsec); + + // Filename (limited to 64 characters) + if (filename) + p += sprintf(p, "%cS%.*s", ETHANLOG_FIELD_DELIM, ETHANLOG_MAX_FILE_NAME_LENGTH, filename); + + // Function name (limited to 128 characters) + if (function) + p += sprintf(p, "%cF%.*s", ETHANLOG_FIELD_DELIM, ETHANLOG_MAX_FUNC_NAME_LENGTH, function); + + // We deliberately don't include the pid, it is disabled on PROD builds in + // Dobby (the consumer of the pipe) due to the overhead of aligning the pids + // inside and outside the containers. + // p += sprintf(p, "%cP%x", ETHANLOG_FIELD_DELIM, getpid()); + + // Line number + if (line > 0) + p += sprintf(p, "%cN%d", ETHANLOG_FIELD_DELIM, line); + + // Finally the start of the message - "::" + p += sprintf(p, "%cM", ETHANLOG_FIELD_DELIM); + +#pragma GCC diagnostic pop + + return p - buf; +} + +// ----------------------------------------------------------------------------- +/** + * @brief Main logging function, this constructs the message to send in the + * pipe and sends it. + * + * It log line wrapping is enabled, then multiple message packages could be sent + * for a single log message, with the wrap indicator appended to all but the last + * message package. If wrapping is disabled (the default) then the message will + * be truncated if it exceeds the maximum. + * + * Messages may also be queued if the pipe is blocked, if the + * ETHAN_LOGGING_QUEUE_SIZE environment variable is set to a non-zero value, + * to prevent log messages from being dropped due to backpressure on the pipe. + * If the queue is full then messages will be dropped and the code will attempt + * to add a log message indicating that messages have been dropped due to + * backpressure. + * + * Returns the 0 on success and -1 on error with errno set to indicate the error. + */ +extern "C" int ethanlog_vprint(int level, const char *filename, + const char *function, int line, + const char *format, va_list ap) +{ + // Run the sanity checks first + if ((level < ETHAN_LOG_FATAL) || (level > ETHAN_LOG_MILESTONE)) + { + errno = EINVAL; + return -1; + } + + // Initialise the pipe if we haven't already + if (gEthanlogPipefd == ETHANLOG_PIPE_UNINITIALIZED) + { + ethanLogInit(); + } + if (gEthanlogPipefd == ETHANLOG_PIPE_ERROR) + { + errno = EPIPE; + return -1; + } + if (gEthanlogPipefd == ETHANLOG_PIPE_REDIRECT_CONSOLE) + { + return ethanlogToConsole(level, filename, function, line, format, ap); + } + + // Populate the start of the log message buffer with prefix information + // (timestamp, file, function, line number etc) this is constant for all + // log lines even when wrapping is enabled. + char buf[ETHANLOG_MAX_LOG_MSG_LENGTH]; + const size_t wrapIndicatorLen = gEthanLogWrapEnabled ? gEthanLogWrapIndicatorLen : 0; + const size_t prefixLen = ethanlogPopulateMsgPrefix(level, filename, function, line, buf); + const size_t maxLineLen = (ETHANLOG_MAX_LOG_MSG_LENGTH - prefixLen - wrapIndicatorLen - 1); + + // If wrapping is not enabled then just write as much of the message as + // we can into the buffer + if (!gEthanLogWrapEnabled) + { + int messageLen = vsnprintf(buf + prefixLen, maxLineLen, format, ap); + if (messageLen < 0) + return -1; + + messageLen = std::min(messageLen, maxLineLen); + buf[prefixLen + messageLen] = ETHANLOG_RECORD_DELIM; + return ethanlogWriteMessage(buf, prefixLen + messageLen + 1); + } + else + { + // If wrapping is enabled then need to format the message into + // a temporary buffer first so we can split it across multiple log + // lines if needed. + char messageBuf[4096]; + int messageLen = vsnprintf(messageBuf, sizeof(messageBuf), format, ap); + if (messageLen < 0) + return -1; + + messageLen = std::min(messageLen, sizeof(messageBuf)); + + // Write the log message in chunks of maxLineLen, appending the wrap + // indicator and record delimiter as needed. + int pos = 0; + while (pos < messageLen) + { + int lineLen = std::min(messageLen - pos, maxLineLen); + + // Copy the message into the buffer + memcpy(buf + prefixLen, messageBuf + pos, lineLen); + pos += lineLen; + + // Check if we should append the wrap indicator character(s) + if ((pos < messageLen) && (wrapIndicatorLen > 0)) + { + memcpy(buf + prefixLen + lineLen, gEthanLogWrapIndicator, wrapIndicatorLen); + lineLen += wrapIndicatorLen; + } + + // Append the log record delimiter at the end of the message + buf[prefixLen + lineLen] = ETHANLOG_RECORD_DELIM; + if (ethanlogWriteMessage(buf, prefixLen + lineLen + 1) < 0) + return -1; + } + } + + return 0; +} + +extern "C" void vethanlog(int level, const char *filename, const char *function, + int line, const char *format, va_list ap) +{ + (void) ethanlog_vprint(level, filename, function, line, format, ap); +} + +extern "C" void ethanlog(int level, const char *filename, const char *function, + int line, const char *format, ...) +{ + va_list vl; + va_start(vl, format); + (void) ethanlog_vprint(level, filename, function, line, format, vl); + va_end(vl); +} diff --git a/plugins/EthanLog/source/EthanLogLoop.cpp b/plugins/EthanLog/source/EthanLogLoop.cpp index e2b340bd..4dc1b81e 100644 --- a/plugins/EthanLog/source/EthanLogLoop.cpp +++ b/plugins/EthanLog/source/EthanLogLoop.cpp @@ -124,7 +124,7 @@ int EthanLogLoop::addClient(const ContainerId& id, const std::string &tag, // attempt to increase the pipe size limit to 256kB, this is quadruple // the default limit of 64kB const int loggingPipeSize = 256 * 1024; - if (fcntl(fds[1], F_SETPIPE_SZ, loggingPipeSize) != 0) + if (fcntl(fds[1], F_SETPIPE_SZ, loggingPipeSize) != loggingPipeSize) { AI_LOG_SYS_WARN(errno, "failed to set pipe size for logging pipe"); } From 6254ec4380c1964c9a8fe6e88ac7b4b08818c646 Mon Sep 17 00:00:00 2001 From: Ben Gray Date: Thu, 2 Apr 2026 16:15:35 +0100 Subject: [PATCH 2/5] Some fixes to avoid appending null characters into the log message. --- plugins/EthanLog/client/lib/CMakeLists.txt | 4 ++-- plugins/EthanLog/client/lib/source/ethanlog.cpp | 15 ++++++++------- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/plugins/EthanLog/client/lib/CMakeLists.txt b/plugins/EthanLog/client/lib/CMakeLists.txt index c1f1d33f..1e6bc56c 100644 --- a/plugins/EthanLog/client/lib/CMakeLists.txt +++ b/plugins/EthanLog/client/lib/CMakeLists.txt @@ -17,7 +17,7 @@ add_library( ethanlog SHARED - source/ethanlog.c + source/ethanlog.cpp ) @@ -32,7 +32,7 @@ target_include_directories( ethanlog set_target_properties( ethanlog PROPERTIES PUBLIC_HEADER include/ethanlog.h - VERSION ${DOBBY_MAJOR_VERSION}.1.0 + VERSION ${DOBBY_MAJOR_VERSION}.2.0 SOVERSION ${DOBBY_MAJOR_VERSION} ) diff --git a/plugins/EthanLog/client/lib/source/ethanlog.cpp b/plugins/EthanLog/client/lib/source/ethanlog.cpp index 8c514b84..2d689fb1 100644 --- a/plugins/EthanLog/client/lib/source/ethanlog.cpp +++ b/plugins/EthanLog/client/lib/source/ethanlog.cpp @@ -127,7 +127,7 @@ static void ethanLogInit() int queueSize = atoi(env); if (queueSize > 0) { - gEthanLogMaxQueuedMessages = std::max(queueSize, 512UL); + gEthanLogMaxQueuedMessages = std::min(queueSize, 1024UL); } } @@ -245,10 +245,11 @@ static std::string ethanlogCreateDroppedMessage(int count) char buf[ETHANLOG_MAX_LOG_MSG_LENGTH]; const size_t prefixLen = ethanlogPopulateMsgPrefix(ETHAN_LOG_WARNING, nullptr, nullptr, -1, buf); + const size_t maxMsgLen = ETHANLOG_MAX_LOG_MSG_LENGTH - prefixLen - 1; - int msgLen = snprintf(buf + prefixLen, sizeof(buf) - prefixLen - 1, + int msgLen = snprintf(buf + prefixLen, maxMsgLen, "Dropped %d log messages due to backpressure", count); - msgLen = std::min(msgLen, (ETHANLOG_MAX_LOG_MSG_LENGTH - prefixLen - 2)); + msgLen = std::min(msgLen, (maxMsgLen - 1)); buf[prefixLen + msgLen] = ETHANLOG_RECORD_DELIM; @@ -332,7 +333,7 @@ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) if (droppedMessages > 0) { const auto msg = ethanlogCreateDroppedMessage(droppedMessages); - if (ethanlogWriteToPipe(msg.data(), msg.size()) == false) + if (!ethanlogWriteToPipe(msg.data(), msg.size())) { queuedMessages.emplace_back(msg); queuedMessageCount++; @@ -347,7 +348,7 @@ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) // in and filled the pipe and the queued messages again. So we try and write, // if fails then we try and queue the message again (which may fail if another // thread has filled the queue in the meantime). - if (ethanlogWriteToPipe(buf, len) == false) + if (!ethanlogWriteToPipe(buf, len)) { std::lock_guard locker(queueMessageLock); @@ -535,7 +536,7 @@ extern "C" int ethanlog_vprint(int level, const char *filename, if (messageLen < 0) return -1; - messageLen = std::min(messageLen, maxLineLen); + messageLen = std::min(messageLen, (maxLineLen - 1)); buf[prefixLen + messageLen] = ETHANLOG_RECORD_DELIM; return ethanlogWriteMessage(buf, prefixLen + messageLen + 1); } @@ -549,7 +550,7 @@ extern "C" int ethanlog_vprint(int level, const char *filename, if (messageLen < 0) return -1; - messageLen = std::min(messageLen, sizeof(messageBuf)); + messageLen = std::min(messageLen, sizeof(messageBuf) - 1); // Write the log message in chunks of maxLineLen, appending the wrap // indicator and record delimiter as needed. From eed4ec4c42fcb18adf35c343226ddb04ace9ba8f Mon Sep 17 00:00:00 2001 From: Ben Gray Date: Thu, 2 Apr 2026 16:38:34 +0100 Subject: [PATCH 3/5] Added some extra protection if multiple threads start using the library at the same time. --- .../EthanLog/client/lib/source/ethanlog.cpp | 110 +++++++++--------- 1 file changed, 57 insertions(+), 53 deletions(-) diff --git a/plugins/EthanLog/client/lib/source/ethanlog.cpp b/plugins/EthanLog/client/lib/source/ethanlog.cpp index 2d689fb1..a6846da3 100644 --- a/plugins/EthanLog/client/lib/source/ethanlog.cpp +++ b/plugins/EthanLog/client/lib/source/ethanlog.cpp @@ -57,7 +57,7 @@ static_assert(ETHANLOG_MAX_LOG_MSG_LENGTH > (64 + ETHANLOG_MAX_FUNC_NAME_LENGTH + ETHANLOG_MAX_FILE_NAME_LENGTH + ETHANLOG_MAX_WRAP_INDICATOR_LEN), "Max log message length must be large enough to hold the max size of all fields"); -static std::atomic gEthanlogPipefd = ETHANLOG_PIPE_UNINITIALIZED; +static std::atomic gEthanlogPipefd{ETHANLOG_PIPE_UNINITIALIZED}; // The number of log messages to allow in a burst before we start dropping messages, this is // used to prevent a flood of log messages from overwhelming the logging system and causing @@ -65,7 +65,7 @@ static size_t gEthanLogMaxQueuedMessages = 0; // Log wrapping is disabled by default, it can be enabled by setting the // ETHAN_LOGGING_ENABLE_WRAP environment variable to "1". -static std::atomic gEthanLogWrapEnabled = false; +static bool gEthanLogWrapEnabled = false; // The wrap indicator is the set of characters to append to the end of a // log message when it is too long and has been truncated. @@ -90,66 +90,70 @@ static size_t ethanlogPopulateMsgPrefix(int level, const char *filename, */ static void ethanLogInit() { - const char *env = getenv("ETHAN_LOGGING_TO_CONSOLE"); - if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) + static std::once_flag initFlag; + std::call_once(initFlag, []() { - gEthanlogPipefd = ETHANLOG_PIPE_REDIRECT_CONSOLE; - return; - } - - // check if log line wrapping should be enabled - env = getenv("ETHAN_LOGGING_ENABLE_WRAP"); - if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) - { - gEthanLogWrapEnabled = true; - } + const char *env = getenv("ETHAN_LOGGING_TO_CONSOLE"); + if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) + { + gEthanlogPipefd = ETHANLOG_PIPE_REDIRECT_CONSOLE; + return; + } - if (gEthanLogWrapEnabled) - { - // check if a custom log wrapping indicator is set, if not use the default - env = getenv("ETHAN_LOGGING_WRAP_INDICATOR"); - if ((env != nullptr) && (env[0] != '\0')) + // check if log line wrapping should be enabled + env = getenv("ETHAN_LOGGING_ENABLE_WRAP"); + if ((env != nullptr) && (env[0] == '1') && (env[1] == '\0')) { - strncpy(gEthanLogWrapIndicator, env, ETHANLOG_MAX_WRAP_INDICATOR_LEN); - gEthanLogWrapIndicator[ETHANLOG_MAX_WRAP_INDICATOR_LEN] = '\0'; + gEthanLogWrapEnabled = true; } - else + + if (gEthanLogWrapEnabled) { - strcpy(gEthanLogWrapIndicator, ETHANLOG_WRAP_INDICATOR); + // check if a custom log wrapping indicator is set, if not use the default + env = getenv("ETHAN_LOGGING_WRAP_INDICATOR"); + if ((env != nullptr) && (env[0] != '\0')) + { + strncpy(gEthanLogWrapIndicator, env, ETHANLOG_MAX_WRAP_INDICATOR_LEN); + gEthanLogWrapIndicator[ETHANLOG_MAX_WRAP_INDICATOR_LEN] = '\0'; + } + else + { + strcpy(gEthanLogWrapIndicator, ETHANLOG_WRAP_INDICATOR); + } + gEthanLogWrapIndicatorLen = strlen(gEthanLogWrapIndicator); } - gEthanLogWrapIndicatorLen = strlen(gEthanLogWrapIndicator); - } - // check if want to enable the log message queue - env = getenv("ETHAN_LOGGING_QUEUE_SIZE"); - if (env != nullptr) - { - int queueSize = atoi(env); - if (queueSize > 0) + // check if want to enable the log message queue + env = getenv("ETHAN_LOGGING_QUEUE_SIZE"); + if (env != nullptr) { - gEthanLogMaxQueuedMessages = std::min(queueSize, 1024UL); + int queueSize = atoi(env); + if (queueSize > 0) + { + gEthanLogMaxQueuedMessages = std::min(queueSize, 1024UL); + } } - } - // the following environment variable is set by the hypervisor, it - // tells us the number of open file descriptor to use for logging. - env = getenv("ETHAN_LOGGING_PIPE"); - if (env == nullptr) - { - gEthanlogPipefd = ETHANLOG_PIPE_ERROR; - return; - } + // the following environment variable is set by the hypervisor, it + // tells us the number of open file descriptor to use for logging. + env = getenv("ETHAN_LOGGING_PIPE"); + if (env == nullptr) + { + gEthanlogPipefd = ETHANLOG_PIPE_ERROR; + return; + } - // the actual pipe fd - int pipeFd = atoi(env); - if ((pipeFd < 3) || (pipeFd > 2048)) - { - gEthanlogPipefd = ETHANLOG_PIPE_ERROR; - } - else - { - gEthanlogPipefd = pipeFd; - } + // the actual pipe fd + int pipeFd = atoi(env); + if ((pipeFd < 3) || (pipeFd > 2048)) + { + gEthanlogPipefd = ETHANLOG_PIPE_ERROR; + } + else + { + gEthanlogPipefd = pipeFd; + } + }); } // ----------------------------------------------------------------------------- @@ -277,7 +281,7 @@ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) // out of order). if (queuedMessageCount > 0) { - std::lock_guard locker(queueMessageLock); + std::lock_guard locker(queueMessageLock); while (!queuedMessages.empty()) { @@ -350,7 +354,7 @@ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) // thread has filled the queue in the meantime). if (!ethanlogWriteToPipe(buf, len)) { - std::lock_guard locker(queueMessageLock); + std::lock_guard locker(queueMessageLock); if (queuedMessages.size() < gEthanLogMaxQueuedMessages) { From 081e1ec13d01d581d7e53d03064dab0f6cca4286 Mon Sep 17 00:00:00 2001 From: Ben Gray Date: Thu, 2 Apr 2026 19:43:06 +0100 Subject: [PATCH 4/5] Fixed C++11 build issue. --- plugins/EthanLog/client/lib/source/ethanlog.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/plugins/EthanLog/client/lib/source/ethanlog.cpp b/plugins/EthanLog/client/lib/source/ethanlog.cpp index a6846da3..1eb9dcfe 100644 --- a/plugins/EthanLog/client/lib/source/ethanlog.cpp +++ b/plugins/EthanLog/client/lib/source/ethanlog.cpp @@ -268,11 +268,11 @@ static std::string ethanlogCreateDroppedMessage(int count) */ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) { - static std::atomic droppedMessages = 0; + static std::atomic droppedMessages{0}; static std::mutex queueMessageLock; static std::deque queuedMessages; - static std::atomic queuedMessageCount = 0; + static std::atomic queuedMessageCount{0}; // First check if we have queued messages, if we do then we need to write // those out before writing the new message, to ensure messages are written From 22978b013acdc87b465465d09157cca445a0dfd2 Mon Sep 17 00:00:00 2001 From: Ben Gray Date: Fri, 3 Apr 2026 14:22:17 +0100 Subject: [PATCH 5/5] Addressed some review comments. --- plugins/EthanLog/client/lib/CMakeLists.txt | 5 +++ .../EthanLog/client/lib/source/ethanlog.cpp | 39 +++++++++++++------ 2 files changed, 33 insertions(+), 11 deletions(-) diff --git a/plugins/EthanLog/client/lib/CMakeLists.txt b/plugins/EthanLog/client/lib/CMakeLists.txt index 1e6bc56c..9b996aa4 100644 --- a/plugins/EthanLog/client/lib/CMakeLists.txt +++ b/plugins/EthanLog/client/lib/CMakeLists.txt @@ -28,6 +28,11 @@ target_include_directories( ethanlog $ ) +target_link_libraries( ethanlog + PUBLIC + Threads::Threads + + ) set_target_properties( ethanlog PROPERTIES diff --git a/plugins/EthanLog/client/lib/source/ethanlog.cpp b/plugins/EthanLog/client/lib/source/ethanlog.cpp index 1eb9dcfe..e069746b 100644 --- a/plugins/EthanLog/client/lib/source/ethanlog.cpp +++ b/plugins/EthanLog/client/lib/source/ethanlog.cpp @@ -27,6 +27,7 @@ #include #include #include +#include #include #include @@ -59,8 +60,10 @@ static_assert(ETHANLOG_MAX_LOG_MSG_LENGTH > static std::atomic gEthanlogPipefd{ETHANLOG_PIPE_UNINITIALIZED}; -// The number of log messages to allow in a burst before we start dropping messages, this is -// used to prevent a flood of log messages from overwhelming the logging system and causing +// The number of log messages to internally queue before we start dropping messages, +// this is disabled by default (max is 0) but can be enabled by setting the +// ETHAN_LOGGING_QUEUE_SIZE environment variable to a positive integer value +// (up to 1024). static size_t gEthanLogMaxQueuedMessages = 0; // Log wrapping is disabled by default, it can be enabled by setting the @@ -160,7 +163,7 @@ static void ethanLogInit() /** * @brief Simple logging function that writes the log message to the console. * - * This function is used if ETHAN_LOGGING_TO_CONSOLE=1 i set in the console. + * This function is used if ETHAN_LOGGING_TO_CONSOLE=1 is set in the console. * */ static int ethanlogToConsole(int level, const char *filename, const char *function, @@ -202,7 +205,10 @@ static int ethanlogToConsole(int level, const char *filename, const char *functi const int stream = (level <= ETHAN_LOG_WARNING) ? STDERR_FILENO : STDOUT_FILENO; return dprintf(stream, "%s %s: < S:%s F:%s L:%d > %s\n", - tbuf, prefix, filename ?: "?", function ?: "?", line, mbuf); + tbuf, prefix, + filename ? filename : "?", + function ? function : "?", + line, mbuf); } // ----------------------------------------------------------------------------- @@ -368,7 +374,7 @@ static int ethanlogWriteMessageWithQueuing(const char* buf, size_t len) return -1; } - return 0; + return len; } // ----------------------------------------------------------------------------- @@ -394,7 +400,7 @@ static int ethanlogWriteMessage(const char* buf, size_t len) if (!ethanlogWriteToPipe(buf, len)) return -1; else - return 0; + return len; } // ----------------------------------------------------------------------------- @@ -412,7 +418,7 @@ static size_t ethanlogPopulateMsgPrefix(int level, const char *filename, const char *function, int line, char* const buf) { - char* p = buf; + char *p = buf; *p++ = ETHANLOG_RECORD_DELIM; @@ -449,14 +455,20 @@ static size_t ethanlogPopulateMsgPrefix(int level, const char *filename, #pragma GCC diagnostic ignored "-Wdeprecated-declarations" // Timestamp for the log - timespec ts = {.tv_sec = 0, .tv_nsec = 0}; + timespec ts = {}; if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) ts.tv_sec = ts.tv_nsec = 0; p += sprintf(p, "%cT%08lx.%08lx", ETHANLOG_FIELD_DELIM, ts.tv_sec, ts.tv_nsec); // Filename (limited to 64 characters) if (filename) + { + const char *basename = strrchr(filename, '/'); + if (basename != nullptr) + filename = (basename + 1); + p += sprintf(p, "%cS%.*s", ETHANLOG_FIELD_DELIM, ETHANLOG_MAX_FILE_NAME_LENGTH, filename); + } // Function name (limited to 128 characters) if (function) @@ -556,6 +568,8 @@ extern "C" int ethanlog_vprint(int level, const char *filename, messageLen = std::min(messageLen, sizeof(messageBuf) - 1); + int totalWritten = 0; + // Write the log message in chunks of maxLineLen, appending the wrap // indicator and record delimiter as needed. int pos = 0; @@ -576,12 +590,15 @@ extern "C" int ethanlog_vprint(int level, const char *filename, // Append the log record delimiter at the end of the message buf[prefixLen + lineLen] = ETHANLOG_RECORD_DELIM; - if (ethanlogWriteMessage(buf, prefixLen + lineLen + 1) < 0) + int written = ethanlogWriteMessage(buf, prefixLen + lineLen + 1); + if (written < 0) return -1; + + totalWritten += written; } - } - return 0; + return totalWritten; + } } extern "C" void vethanlog(int level, const char *filename, const char *function,