<p>laforge <strong>submitted</strong> this change.</p><p><a href="https://gerrit.osmocom.org/c/libosmocore/+/20296">View Change</a></p><div style="white-space:pre-wrap">Approvals:
Jenkins Builder: Verified
pespin: Looks good to me, but someone else must approve
osmith: Looks good to me, but someone else must approve
laforge: Looks good to me, approved
</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">logging: Change stderr + file target to use non-blocking write<br><br>So far, we used blocking, buffered fwrite() to write to stderr<br>and file targets. This causes problems if there are [slow] consumers<br>causing delays, such as gnome-terminal (when the program is started<br>interactively) or systemd/journald (where we observe 64..128ms blocks on<br>stderr).<br><br>This patch introduces stderr/file based logging via write_queue<br>and osmo_select_main(), i.e. switch from glibc-buffered, blocking<br>to internally buffered, non-blocking writes.<br><br>* when osmo_stderr_target is created via application.c, we create it<br> in blocking stream mode for backwards compatibility, particularly<br> for [smaller] programs that don't use osmo_select_main()<br><br>* when the VTY code encounters 'log stderr' or 'log file FILENAME',<br> we switch that respective target to non-blocking write-queue mode,<br> as this means the application is in fact using osmo_select_main()<br><br>* The config file can now state 'log stderr blocking-io' or<br> 'log file FILENAME blocking-io' to explicitly enforce using blocking<br> stream based I/O<br><br>* The application can at any time use API functions to switch either way<br><br>Closes: OS#4311<br>Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da<br>---<br>M include/osmocom/core/logging.h<br>M src/logging.c<br>M src/vty/logging_vty.c<br>M tests/logging/logging_vty_test.c<br>4 files changed, 313 insertions(+), 22 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h</span><br><span>index 343f976..a554adc 100644</span><br><span>--- a/include/osmocom/core/logging.h</span><br><span>+++ b/include/osmocom/core/logging.h</span><br><span>@@ -297,8 +297,11 @@</span><br><span> </span><br><span> union {</span><br><span> struct {</span><br><span style="color: hsl(120, 100%, 40%);">+ /* direct, blocking output via stdio */</span><br><span> FILE *out;</span><br><span> const char *fname;</span><br><span style="color: hsl(120, 100%, 40%);">+ /* indirect output via write_queue and osmo_select_main() */</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wqueue;</span><br><span> } tgt_file;</span><br><span> </span><br><span> struct {</span><br><span>@@ -408,6 +411,8 @@</span><br><span> struct log_target *log_target_create_systemd(bool raw);</span><br><span> void log_target_systemd_set_raw(struct log_target *target, bool raw);</span><br><span> int log_target_file_reopen(struct log_target *tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+int log_target_file_switch_to_stream(struct log_target *tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+int log_target_file_switch_to_wqueue(struct log_target *tgt);</span><br><span> int log_targets_reopen(void);</span><br><span> </span><br><span> void log_add_target(struct log_target *target);</span><br><span>diff --git a/src/logging.c b/src/logging.c</span><br><span>index 1d139d5..5c6b993 100644</span><br><span>--- a/src/logging.c</span><br><span>+++ b/src/logging.c</span><br><span>@@ -35,6 +35,7 @@</span><br><span> #include <stdlib.h></span><br><span> #include <stdio.h></span><br><span> #include <string.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <unistd.h></span><br><span> </span><br><span> #ifdef HAVE_STRINGS_H</span><br><span> #include <strings.h></span><br><span>@@ -57,6 +58,9 @@</span><br><span> </span><br><span> #include <time.h></span><br><span> #include <sys/time.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <sys/types.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <sys/stat.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <fcntl.h></span><br><span> #include <errno.h></span><br><span> #include <pthread.h></span><br><span> </span><br><span>@@ -65,12 +69,17 @@</span><br><span> #include <osmocom/core/logging.h></span><br><span> #include <osmocom/core/timer.h></span><br><span> #include <osmocom/core/thread.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <osmocom/core/select.h></span><br><span style="color: hsl(120, 100%, 40%);">+#include <osmocom/core/write_queue.h></span><br><span> </span><br><span> #include <osmocom/vty/logging.h> /* for LOGGING_STR. */</span><br><span> </span><br><span> /* maximum length of the log string of a single log event (typically line) */</span><br><span> #define MAX_LOG_SIZE 4096</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+/* maximum number of log statements we queue in file/stderr target write queue */</span><br><span style="color: hsl(120, 100%, 40%);">+#define LOG_WQUEUE_LEN 1024</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> osmo_static_assert(_LOG_CTX_COUNT <= ARRAY_SIZE(((struct log_context*)NULL)->ctx),</span><br><span> enum_logging_ctx_items_fit_in_struct_log_context);</span><br><span> osmo_static_assert(_LOG_FLT_COUNT <= ARRAY_SIZE(((struct log_target*)NULL)->filter_data),</span><br><span>@@ -904,11 +913,32 @@</span><br><span> }</span><br><span> </span><br><span> #if (!EMBEDDED)</span><br><span style="color: hsl(120, 100%, 40%);">+static void _file_output_stream(struct log_target *target, unsigned int level,</span><br><span style="color: hsl(120, 100%, 40%);">+ const char *log)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_ASSERT(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ fputs(log, target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ fflush(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/* output via non-blocking write_queue, doing internal buffering */</span><br><span> static void _file_output(struct log_target *target, unsigned int level,</span><br><span> const char *log)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">- fprintf(target->tgt_file.out, "%s", log);</span><br><span style="color: hsl(0, 100%, 40%);">- fflush(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ int len = strlen(log);</span><br><span style="color: hsl(120, 100%, 40%);">+ struct msgb *msg;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_ASSERT(target->tgt_file.wqueue);</span><br><span style="color: hsl(120, 100%, 40%);">+ msg = msgb_alloc_c(target->tgt_file.wqueue, len, "log_file_msg");</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!msg)</span><br><span style="color: hsl(120, 100%, 40%);">+ return;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* we simply enqueue the log message to a write queue here, to avoid any blocking</span><br><span style="color: hsl(120, 100%, 40%);">+ * writes on the output file. The write queue will tell us once the file is writable</span><br><span style="color: hsl(120, 100%, 40%);">+ * and call _file_wq_write_cb() */</span><br><span style="color: hsl(120, 100%, 40%);">+ memcpy(msg->data, log, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_put(msg, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg);</span><br><span> }</span><br><span> #endif</span><br><span> </span><br><span>@@ -972,7 +1002,7 @@</span><br><span> </span><br><span> target->type = LOG_TGT_TYPE_STDERR;</span><br><span> target->tgt_file.out = stderr;</span><br><span style="color: hsl(0, 100%, 40%);">- target->output = _file_output;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output = _file_output_stream;</span><br><span> return target;</span><br><span> #else</span><br><span> return NULL;</span><br><span>@@ -980,11 +1010,28 @@</span><br><span> }</span><br><span> </span><br><span> #if (!EMBEDDED)</span><br><span style="color: hsl(0, 100%, 40%);">-/*! Create a new file-based log target</span><br><span style="color: hsl(120, 100%, 40%);">+/* write-queue tells us we should write another msgb (log line) to the output fd */</span><br><span style="color: hsl(120, 100%, 40%);">+static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ int rc;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = write(ofd->fd, msgb_data(msg), msgb_length(msg));</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ return rc;</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc != msgb_length(msg)) {</span><br><span style="color: hsl(120, 100%, 40%);">+ /* pull the number of bytes we have already written */</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_pull(msg, rc);</span><br><span style="color: hsl(120, 100%, 40%);">+ /* ask write_queue to re-insert the msgb at the head of the queue */</span><br><span style="color: hsl(120, 100%, 40%);">+ return -EAGAIN;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ return 0;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/*! Create a new file-based log target using buffered, blocking stream output</span><br><span> * \param[in] fname File name of the new log file</span><br><span> * \returns Log target in case of success, NULL otherwise</span><br><span> */</span><br><span style="color: hsl(0, 100%, 40%);">-struct log_target *log_target_create_file(const char *fname)</span><br><span style="color: hsl(120, 100%, 40%);">+struct log_target *log_target_create_file_stream(const char *fname)</span><br><span> {</span><br><span> struct log_target *target;</span><br><span> </span><br><span>@@ -998,9 +1045,193 @@</span><br><span> log_target_destroy(target);</span><br><span> return NULL;</span><br><span> }</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output = _file_output_stream;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.fname = talloc_strdup(target, fname);</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ return target;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/*! switch from non-blocking/write-queue to blocking + buffered stream output</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] target log target which we should switch</span><br><span style="color: hsl(120, 100%, 40%);">+ * \return 0 on success; 1 if already switched before; negative on error */</span><br><span style="color: hsl(120, 100%, 40%);">+int log_target_file_switch_to_stream(struct log_target *target)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wq;</span><br><span style="color: hsl(120, 100%, 40%);">+ const char *name;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target)</span><br><span style="color: hsl(120, 100%, 40%);">+ return -ENODEV;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* this only works for file/stderr targets */</span><br><span style="color: hsl(120, 100%, 40%);">+ switch (target->type) {</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(120, 100%, 40%);">+ name = target->tgt_file.fname;</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(120, 100%, 40%);">+ name = "stderr";</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ default:</span><br><span style="color: hsl(120, 100%, 40%);">+ return -EINVAL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->tgt_file.out) {</span><br><span style="color: hsl(120, 100%, 40%);">+ /* target has already been switched over */</span><br><span style="color: hsl(120, 100%, 40%);">+ return 1;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to blocking stream I/O\n", name);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ wq = target->tgt_file.wqueue;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_ASSERT(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* re-open output as stream */</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_STDERR)</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.out = stderr;</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.out = fopen(target->tgt_file.fname, "a");</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target->tgt_file.out) {</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as blocking stream I/O: %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ name, strerror(errno));</span><br><span style="color: hsl(120, 100%, 40%);">+ return -EIO;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* synchronously write anything left in the queue */</span><br><span style="color: hsl(120, 100%, 40%);">+ while (!llist_empty(&wq->msg_queue)) {</span><br><span style="color: hsl(120, 100%, 40%);">+ struct msgb *msg = msgb_dequeue(&wq->msg_queue);</span><br><span style="color: hsl(120, 100%, 40%);">+ fwrite(msgb_data(msg), msgb_length(msg), 1, target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_free(msg);</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* now that everything succeeded, we can finally close the old output fd */</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_FILE) {</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fd_unregister(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ close(wq->bfd.fd);</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* release the queue itself */</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.wqueue = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output = _file_output_stream;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->raw_output = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ return 0;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/*! switch from blocking + buffered file output to non-blocking write-queue based output.</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] target log target which we should switch</span><br><span style="color: hsl(120, 100%, 40%);">+ * \return 0 on success; 1 if already switched before; negative on error */</span><br><span style="color: hsl(120, 100%, 40%);">+int log_target_file_switch_to_wqueue(struct log_target *target)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wq;</span><br><span style="color: hsl(120, 100%, 40%);">+ const char *name;</span><br><span style="color: hsl(120, 100%, 40%);">+ int rc;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target)</span><br><span style="color: hsl(120, 100%, 40%);">+ return -ENODEV;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* this only works for file/stderr targets */</span><br><span style="color: hsl(120, 100%, 40%);">+ switch (target->type) {</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(120, 100%, 40%);">+ name = target->tgt_file.fname;</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(120, 100%, 40%);">+ name = "stderr";</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ default:</span><br><span style="color: hsl(120, 100%, 40%);">+ return -EINVAL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target->tgt_file.out) {</span><br><span style="color: hsl(120, 100%, 40%);">+ /* target has already been switched over */</span><br><span style="color: hsl(120, 100%, 40%);">+ return 1;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to non-blocking I/O\n", name);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ /* we create a ~640kB sized talloc pool within the write-queue to ensure individual</span><br><span style="color: hsl(120, 100%, 40%);">+ * log lines (stored as msgbs) will not put result in malloc() calls, and also to</span><br><span style="color: hsl(120, 100%, 40%);">+ * reduce the OOM probability within logging, as the pool is already allocated */</span><br><span style="color: hsl(120, 100%, 40%);">+ wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_WQUEUE_LEN*(sizeof(struct msgb)+512));</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!wq)</span><br><span style="color: hsl(120, 100%, 40%);">+ return -ENOMEM;</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_wqueue_init(wq, LOG_WQUEUE_LEN);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ fflush(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_FILE) {</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as non-blocking I/O: %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ name, strerror(errno));</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ return -errno;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ } else {</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = STDERR_FILENO;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.fd = rc;</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.when = OSMO_FD_WRITE;</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->write_cb = _file_wq_write_cb;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = osmo_fd_register(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ return -EIO;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.wqueue = wq;</span><br><span> target->output = _file_output;</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ /* now that everything succeeded, we can finally close the old output stream */</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_FILE)</span><br><span style="color: hsl(120, 100%, 40%);">+ fclose(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.out = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ return 0;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/*! Create a new file-based log target using non-blocking write_queue</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] fname File name of the new log file</span><br><span style="color: hsl(120, 100%, 40%);">+ * \returns Log target in case of success, NULL otherwise</span><br><span style="color: hsl(120, 100%, 40%);">+ */</span><br><span style="color: hsl(120, 100%, 40%);">+struct log_target *log_target_create_file(const char *fname)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ struct log_target *target;</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wq;</span><br><span style="color: hsl(120, 100%, 40%);">+ int rc;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ target = log_target_create();</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target)</span><br><span style="color: hsl(120, 100%, 40%);">+ return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ target->type = LOG_TGT_TYPE_FILE;</span><br><span style="color: hsl(120, 100%, 40%);">+ /* we create a ~640kB sized talloc pool within the write-queue to ensure individual</span><br><span style="color: hsl(120, 100%, 40%);">+ * log lines (stored as msgbs) will not put result in malloc() calls, and also to</span><br><span style="color: hsl(120, 100%, 40%);">+ * reduce the OOM probability within logging, as the pool is already allocated */</span><br><span style="color: hsl(120, 100%, 40%);">+ wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_WQUEUE_LEN*(sizeof(struct msgb)+512));</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!wq) {</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_destroy(target);</span><br><span style="color: hsl(120, 100%, 40%);">+ return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_wqueue_init(wq, LOG_WQUEUE_LEN);</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.fd = open(fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (wq->bfd.fd < 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_destroy(target);</span><br><span style="color: hsl(120, 100%, 40%);">+ return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.when = OSMO_FD_WRITE;</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->write_cb = _file_wq_write_cb;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = osmo_fd_register(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_destroy(target);</span><br><span style="color: hsl(120, 100%, 40%);">+ return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.wqueue = wq;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output = _file_output;</span><br><span> target->tgt_file.fname = talloc_strdup(target, fname);</span><br><span> </span><br><span> return target;</span><br><span>@@ -1040,17 +1271,33 @@</span><br><span> * \param[in] target log target to unregister, close and delete */</span><br><span> void log_target_destroy(struct log_target *target)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> /* just in case, to make sure we don't have any references */</span><br><span> log_del_target(target);</span><br><span> </span><br><span> #if (!EMBEDDED)</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wq;</span><br><span> switch (target->type) {</span><br><span> case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(0, 100%, 40%);">- if (target->tgt_file.out == NULL)</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- fclose(target->tgt_file.out);</span><br><span style="color: hsl(0, 100%, 40%);">- target->tgt_file.out = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->tgt_file.out) {</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_FILE)</span><br><span style="color: hsl(120, 100%, 40%);">+ fclose(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.out = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ wq = target->tgt_file.wqueue;</span><br><span style="color: hsl(120, 100%, 40%);">+ if (wq) {</span><br><span style="color: hsl(120, 100%, 40%);">+ if (wq->bfd.fd >= 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->type == LOG_TGT_TYPE_FILE)</span><br><span style="color: hsl(120, 100%, 40%);">+ close(wq->bfd.fd);</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.fd = -1;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fd_unregister(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_wqueue_clear(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free(wq);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.wqueue = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ talloc_free((void *)target->tgt_file.fname);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.fname = NULL;</span><br><span> break;</span><br><span> #ifdef HAVE_SYSLOG_H</span><br><span> case LOG_TGT_TYPE_SYSLOG:</span><br><span>@@ -1071,13 +1318,33 @@</span><br><span> * \returns 0 in case of success; negative otherwise */</span><br><span> int log_target_file_reopen(struct log_target *target)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">- fclose(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ struct osmo_wqueue *wq;</span><br><span style="color: hsl(120, 100%, 40%);">+ int rc;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- target->tgt_file.out = fopen(target->tgt_file.fname, "a");</span><br><span style="color: hsl(0, 100%, 40%);">- if (!target->tgt_file.out)</span><br><span style="color: hsl(0, 100%, 40%);">- return -errno;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE || target->type == LOG_TGT_TYPE_STDERR);</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_ASSERT(target->tgt_file.out || target->tgt_file.wqueue);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- /* we assume target->output already to be set */</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->tgt_file.out) {</span><br><span style="color: hsl(120, 100%, 40%);">+ fclose(target->tgt_file.out);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->tgt_file.out = fopen(target->tgt_file.fname, "a");</span><br><span style="color: hsl(120, 100%, 40%);">+ if (!target->tgt_file.out)</span><br><span style="color: hsl(120, 100%, 40%);">+ return -errno;</span><br><span style="color: hsl(120, 100%, 40%);">+ } else {</span><br><span style="color: hsl(120, 100%, 40%);">+ wq = target->tgt_file.wqueue;</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fd_unregister(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (wq->bfd.fd >= 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+ close(wq->bfd.fd);</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.fd = -1;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ return -errno;</span><br><span style="color: hsl(120, 100%, 40%);">+ wq->bfd.fd = rc;</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = osmo_fd_register(&wq->bfd);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (rc < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ return rc;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span> </span><br><span> return 0;</span><br><span> }</span><br><span>diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c</span><br><span>index 3b131c2..d33fe5e 100644</span><br><span>--- a/src/vty/logging_vty.c</span><br><span>+++ b/src/vty/logging_vty.c</span><br><span>@@ -835,8 +835,9 @@</span><br><span> }</span><br><span> </span><br><span> DEFUN(cfg_log_stderr, cfg_log_stderr_cmd,</span><br><span style="color: hsl(0, 100%, 40%);">- "log stderr",</span><br><span style="color: hsl(0, 100%, 40%);">- LOG_STR "Logging via STDERR of the process\n")</span><br><span style="color: hsl(120, 100%, 40%);">+ "log stderr [blocking-io]",</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_STR "Logging via STDERR of the process\n"</span><br><span style="color: hsl(120, 100%, 40%);">+ "Use blocking, synchronous I/O\n")</span><br><span> {</span><br><span> struct log_target *tgt;</span><br><span> </span><br><span>@@ -852,6 +853,11 @@</span><br><span> log_add_target(tgt);</span><br><span> }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ if (argc > 0 && !strcmp(argv[0], "blocking-io"))</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_file_switch_to_stream(tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_file_switch_to_wqueue(tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> vty->index = tgt;</span><br><span> vty->node = CFG_LOG_NODE;</span><br><span> </span><br><span>@@ -878,8 +884,9 @@</span><br><span> }</span><br><span> </span><br><span> DEFUN(cfg_log_file, cfg_log_file_cmd,</span><br><span style="color: hsl(0, 100%, 40%);">- "log file .FILENAME",</span><br><span style="color: hsl(0, 100%, 40%);">- LOG_STR "Logging to text file\n" "Filename\n")</span><br><span style="color: hsl(120, 100%, 40%);">+ "log file FILENAME [blocking-io]",</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_STR "Logging to text file\n" "Filename\n"</span><br><span style="color: hsl(120, 100%, 40%);">+ "Use blocking, synchronous I/O\n")</span><br><span> {</span><br><span> const char *fname = argv[0];</span><br><span> struct log_target *tgt;</span><br><span>@@ -896,6 +903,11 @@</span><br><span> log_add_target(tgt);</span><br><span> }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ if (argc > 1 && !strcmp(argv[1], "blocking-io"))</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_file_switch_to_stream(tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_file_switch_to_wqueue(tgt);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> vty->index = tgt;</span><br><span> vty->node = CFG_LOG_NODE;</span><br><span> </span><br><span>@@ -904,7 +916,7 @@</span><br><span> </span><br><span> </span><br><span> DEFUN(cfg_no_log_file, cfg_no_log_file_cmd,</span><br><span style="color: hsl(0, 100%, 40%);">- "no log file .FILENAME",</span><br><span style="color: hsl(120, 100%, 40%);">+ "no log file FILENAME",</span><br><span> NO_STR LOG_STR "Logging to text file\n" "Filename\n")</span><br><span> {</span><br><span> const char *fname = argv[0];</span><br><span>@@ -979,7 +991,10 @@</span><br><span> return 1;</span><br><span> break;</span><br><span> case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(0, 100%, 40%);">- vty_out(vty, "log stderr%s", VTY_NEWLINE);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (tgt->tgt_file.wqueue)</span><br><span style="color: hsl(120, 100%, 40%);">+ vty_out(vty, "log stderr%s", VTY_NEWLINE);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ vty_out(vty, "log stderr blocking-io%s", VTY_NEWLINE);</span><br><span> break;</span><br><span> case LOG_TGT_TYPE_SYSLOG:</span><br><span> #ifdef HAVE_SYSLOG_H</span><br><span>@@ -990,7 +1005,10 @@</span><br><span> #endif</span><br><span> break;</span><br><span> case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(0, 100%, 40%);">- vty_out(vty, "log file %s%s", tgt->tgt_file.fname, VTY_NEWLINE);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (tgt->tgt_file.wqueue)</span><br><span style="color: hsl(120, 100%, 40%);">+ vty_out(vty, "log file %s%s", tgt->tgt_file.fname, VTY_NEWLINE);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ vty_out(vty, "log file %s blocking-io%s", tgt->tgt_file.fname, VTY_NEWLINE);</span><br><span> break;</span><br><span> case LOG_TGT_TYPE_STRRB:</span><br><span> vty_out(vty, "log alarms %zu%s",</span><br><span>diff --git a/tests/logging/logging_vty_test.c b/tests/logging/logging_vty_test.c</span><br><span>index e7019f6..078555e 100644</span><br><span>--- a/tests/logging/logging_vty_test.c</span><br><span>+++ b/tests/logging/logging_vty_test.c</span><br><span>@@ -254,6 +254,7 @@</span><br><span> log_set_print_category_hex(osmo_stderr_target, 0);</span><br><span> log_set_print_level(osmo_stderr_target, 1);</span><br><span> log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);</span><br><span style="color: hsl(120, 100%, 40%);">+ log_target_file_switch_to_wqueue(osmo_stderr_target);</span><br><span> </span><br><span> if (cmdline_config.config_file) {</span><br><span> rc = vty_read_config_file(cmdline_config.config_file, NULL);</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/c/libosmocore/+/20296">change 20296</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/c/libosmocore/+/20296"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: libosmocore </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da </div>
<div style="display:none"> Gerrit-Change-Number: 20296 </div>
<div style="display:none"> Gerrit-PatchSet: 16 </div>
<div style="display:none"> Gerrit-Owner: laforge <laforge@osmocom.org> </div>
<div style="display:none"> Gerrit-Reviewer: Jenkins Builder </div>
<div style="display:none"> Gerrit-Reviewer: laforge <laforge@osmocom.org> </div>
<div style="display:none"> Gerrit-Reviewer: osmith <osmith@sysmocom.de> </div>
<div style="display:none"> Gerrit-Reviewer: pespin <pespin@sysmocom.de> </div>
<div style="display:none"> Gerrit-MessageType: merged </div>