[L] Change in libosmocore[master]: Implement log file target using osmo_io

2 Feb 2026

pespin has submitted this change. ( https://gerrit.osmocom.org/c/libosmocore/+/41925?usp=email )
Change subject: Implement log file target using osmo_io
......................................................................
Implement log file target using osmo_io
Reuse (struct log_target)->tgt_file->wqueue->except_cb to store the iofd
pointer internally, since we are not allowed to change the struct
log_target because it's public and we don't want to break the ABI.
Using the wqueue except_cb is fine since that field was never used.
Related: OS#6918
Change-Id: Ieb6420246454ef59442b1fd7b1d14e2c00fa69a5
---
M src/core/logging_file.c
M tests/logging/logging_test.c
M tests/logging/logging_test.err
3 files changed, 143 insertions(+), 132 deletions(-)
Approvals:
  jolly: Looks good to me, but someone else must approve
  Jenkins Builder: Verified
  laforge: Looks good to me, but someone else must approve
  pespin: Looks good to me, approved

diff --git a/src/core/logging_file.c b/src/core/logging_file.c
index 413a0a7..aa5ef63 100644
--- a/src/core/logging_file.c
+++ b/src/core/logging_file.c
@@ -38,18 +38,22 @@
 #include <osmocom/core/utils.h>
 #include <osmocom/core/select.h>
 #include <osmocom/core/write_queue.h>
+#include <osmocom/core/osmo_io.h>
 #include <osmocom/core/logging_internal.h>
/* maximum number of log statements we queue in file/stderr target write queue */
 #define LOG_WQUEUE_LEN	156
+/* NOTE: We use target->tgt_file.wqueue->except_cb to store the struct osmo_io_fd, because the
+ * struct log_target is public and we cannot add pointers to it under tgt->tgt_file...
+ * It can be moved to target->tgt_file.iofd if we are ever able to make struct log_target private... */
/*! close and re-open a log file (for log file rotation)
  *  \param[in] target log target to re-open
  *  \returns 0 in case of success; negative otherwise */
 int log_target_file_reopen(struct log_target *target)
 {
-	struct osmo_wqueue *wq;
+	struct osmo_io_fd *iofd;
    int rc;
OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE ||
@@ -67,20 +71,22 @@
    }
OSMO_ASSERT(target->tgt_file.wqueue);
-	wq = target->tgt_file.wqueue;
-	if (wq->bfd.fd >= 0) {
-		osmo_fd_unregister(&wq->bfd);
-		close(wq->bfd.fd);
-		wq->bfd.fd = -1;
-	}
+	iofd = (struct osmo_io_fd *)target->tgt_file.wqueue->except_cb;
+	OSMO_ASSERT(iofd);
+	osmo_iofd_close(iofd);
+	target->tgt_file.wqueue->bfd.fd = -1; /* Keep public field changes despite not used internally... */
rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
    if (rc < 0)
    	return -errno;
-	wq->bfd.fd = rc;
-	rc = osmo_fd_register(&wq->bfd);
-	if (rc < 0)
-		return rc;
+
+	rc = osmo_iofd_register(iofd, rc);
+	if (rc < 0) {
+		osmo_iofd_free(iofd);
+		target->tgt_file.wqueue->except_cb = NULL; /* target->tgt_file.iofd = NULL */
+		return -EIO;
+	}
+	target->tgt_file.wqueue->bfd.fd = rc; /* Keep public field changes despite not used internally... */
    return 0;
 }
@@ -91,7 +97,6 @@
  * object. */
 void log_target_file_destroy(struct log_target *target)
 {
-	struct osmo_wqueue *wq;
OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE ||
    	    target->type == LOG_TGT_TYPE_STDERR);
@@ -101,38 +106,21 @@
    		fclose(target->tgt_file.out);
    	target->tgt_file.out = NULL;
    }
-	wq = target->tgt_file.wqueue;
-	if (wq) {
-		if (wq->bfd.fd >= 0) {
-			osmo_fd_unregister(&wq->bfd);
-			if (target->type == LOG_TGT_TYPE_FILE)
-				close(wq->bfd.fd);
-			wq->bfd.fd = -1;
-		}
-		osmo_wqueue_clear(wq);
-		talloc_free(wq);
-		target->tgt_file.wqueue = NULL;
+
+	if (target->tgt_file.wqueue && target->tgt_file.wqueue->except_cb) { /* target->tgt_file.iofd */
+		osmo_iofd_free((struct osmo_io_fd *)target->tgt_file.wqueue->except_cb);
+		target->tgt_file.wqueue->except_cb = NULL; /* target->tgt_file.iofd = NULL */
+		target->tgt_file.wqueue->bfd.fd = -1; /* Keep public field changes despite not used internally... */
    }
+
    talloc_free((void *)target->tgt_file.fname);
    target->tgt_file.fname = NULL;
 }
-/* write-queue tells us we should write another msgb (log line) to the output fd */
-static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg)
-{
-	int rc;
-
-	rc = write(ofd->fd, msgb_data(msg), msgb_length(msg));
-	if (rc < 0)
-		return rc;
-	if (rc != msgb_length(msg)) {
-		/* pull the number of bytes we have already written */
-		msgb_pull(msg, rc);
-		/* ask write_queue to re-insert the msgb at the head of the queue */
-		return -EAGAIN;
-	}
-	return 0;
-}
+static struct osmo_io_ops log_target_file_io_ops = {
+	.read_cb = NULL,
+	.write_cb = NULL,
+};
/* output via buffered, blocking stdio streams */
 static void _file_output_stream(struct log_target *target, unsigned int level,
@@ -147,37 +135,53 @@
 static void _file_raw_output(struct log_target *target, int subsys, unsigned int level, const char *file,
    		     int line, int cont, const char *format, va_list ap)
 {
+	OSMO_ASSERT(target->tgt_file.wqueue && target->tgt_file.wqueue->except_cb);
    struct msgb *msg;
+	struct osmo_io_fd *iofd = (struct osmo_io_fd *)target->tgt_file.wqueue->except_cb;
+	void *pool_ctx = osmo_iofd_get_data(iofd);
    int rc;
-	OSMO_ASSERT(target->tgt_file.wqueue);
-	msg = msgb_alloc_c(target->tgt_file.wqueue, MAX_LOG_SIZE, "log_file_msg");
+	msg = msgb_alloc_c(pool_ctx, MAX_LOG_SIZE, "log_file_msg");
    if (!msg)
    	return;
/* we simply enqueue the log message to a write queue here, to avoid any blocking
     * writes on the output file.  The write queue will tell us once the file is writable
     * and call _file_wq_write_cb() */
-	rc = log_output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level, file, line, cont, format, ap);
+	rc = log_output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level,
+			     file, line, cont, format, ap);
    msgb_put(msg, rc);
-	/* attempt a synchronous, non-blocking write, if the write queue is empty */
-	if (target->tgt_file.wqueue->current_length == 0) {
-		rc = _file_wq_write_cb(&target->tgt_file.wqueue->bfd, msg);
-		if (rc == 0) {
-			/* the write was complete, we can exit early */
-			msgb_free(msg);
-			return;
-		}
-	}
-	/* if we reach here, either we already had elements in the write_queue, or the synchronous write
-	 * failed: enqueue the message to the write_queue (backlog) */
-	if (osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg) < 0) {
+	rc = osmo_iofd_write_msgb(iofd, msg);
+	if (rc < 0) {
    	msgb_free(msg);
    	/* TODO: increment some counter so we can see that messages were dropped */
    }
 }
+void _log_target_file_setup_talloc_pool(struct log_target *target)
+{
+	OSMO_ASSERT(target->tgt_file.wqueue && target->tgt_file.wqueue->except_cb);
+	struct osmo_io_fd *iofd = (struct osmo_io_fd *)target->tgt_file.wqueue->except_cb;
+	if (osmo_iofd_get_data(iofd))
+		return; /* mempool already allocated */
+
+#ifndef ENABLE_PSEUDOTALLOC
+	void *pool_ctx;
+	/* Allocate a talloc pool to avoid malloc() on the first 156
+	* concurrently queued msgbs (~640KB per gsmtap_log target).
+	* Once the talloc_pool is full, new normal talloc chunks will be used. */
+	pool_ctx = _talloc_pooled_object(target, 0, "file_log_msgb_pool",
+					 LOG_WQUEUE_LEN,
+					 (sizeof(struct msgb) + MAX_LOG_SIZE) * LOG_WQUEUE_LEN);
+	osmo_iofd_set_data(iofd, pool_ctx);
+#else
+	/* talloc pools not supported by pseudotalloc, allocate on usual msgb ctx instead: */
+	extern void *tall_msgb_ctx;
+	osmo_iofd_set_data(iofd, tall_msgb_ctx);
+#endif /* ifndef ENABLE_PSEUDOTALLOC */
+}
+
 /*! switch from non-blocking/write-queue to blocking + buffered stream output
  *  \param[in] target log target which we should switch
  *  \return 0 on success; 1 if already switched before; negative on error
@@ -185,7 +189,8 @@
  */
 int log_target_file_switch_to_stream(struct log_target *target)
 {
-	struct osmo_wqueue *wq;
+	struct osmo_io_fd *iofd;
+	unsigned int prev_queue_len;
if (!target)
    	return -ENODEV;
@@ -195,36 +200,70 @@
    	return 1;
    }
-	wq = target->tgt_file.wqueue;
-	OSMO_ASSERT(wq);
-
    /* re-open output as stream */
    if (target->type == LOG_TGT_TYPE_STDERR)
    	target->tgt_file.out = stderr;
    else
    	target->tgt_file.out = fopen(target->tgt_file.fname, "a");
+
    if (!target->tgt_file.out)
    	return -EIO;
-	/* synchronously write anything left in the queue */
-	while (!llist_empty(&wq->msg_queue)) {
-		struct msgb *msg = msgb_dequeue(&wq->msg_queue);
-		fwrite(msgb_data(msg), msgb_length(msg), 1, target->tgt_file.out);
-		msgb_free(msg);
-	}
+	iofd = (struct osmo_io_fd *)target->tgt_file.wqueue->except_cb;
+	prev_queue_len = osmo_iofd_txqueue_len(iofd);
-	/* now that everything succeeded, we can finally close the old output fd */
-	osmo_fd_unregister(&wq->bfd);
-	if (target->type == LOG_TGT_TYPE_FILE)
-		close(wq->bfd.fd);
-	wq->bfd.fd = -1;
-
+	/* now that everything succeeded, we can finally close the old iofd */
+	osmo_iofd_free(iofd);
+	target->tgt_file.wqueue->except_cb = NULL; /* target->tgt_file.iofd = NULL */
+	target->tgt_file.wqueue->bfd.fd = -1; /* Keep public field changes despite not used internally... */
    /* release the queue itself */
-	talloc_free(wq);
+	talloc_free(target->tgt_file.wqueue);
    target->tgt_file.wqueue = NULL;
    target->output = _file_output_stream;
    target->raw_output = NULL;
+
+	if (prev_queue_len > 0)
+		LOGP(DLGLOBAL, LOGL_NOTICE,
+		     "Dropped %u messages switching log target file to stream\n", prev_queue_len);
+
+	return 0;
+}
+
+/* Owns fd on success, closes fd on error. */
+int _log_target_file_setup_iofd(struct log_target *target, int fd)
+{
+	struct osmo_io_fd *iofd;
+	int rc;
+
+	/* XXX: This wq is only created to keep public log_target fields
+	 * similar. It's not really used anymore internally, other than holding a
+	 * struct osmo_io_fd in wq->except_cb...*/
+	target->tgt_file.wqueue = talloc_zero(target, struct osmo_wqueue);
+	OSMO_ASSERT(target->tgt_file.wqueue);
+	osmo_wqueue_init(target->tgt_file.wqueue, LOG_WQUEUE_LEN);
+
+	iofd = osmo_iofd_setup(target, fd, target->tgt_file.fname,
+			       OSMO_IO_FD_MODE_READ_WRITE,
+			       &log_target_file_io_ops, NULL);
+	if (!iofd) {
+		close(fd);
+		return -EIO;
+	}
+	target->tgt_file.wqueue->except_cb = (int (*)(struct osmo_fd *))iofd;
+	target->tgt_file.wqueue->bfd.fd = fd; /* Keep public field changes despite not used internally... */
+
+	_log_target_file_setup_talloc_pool(target);
+	osmo_iofd_set_txqueue_max_length(iofd, OSMO_MAX(osmo_iofd_get_txqueue_max_length(iofd), LOG_WQUEUE_LEN));
+
+	rc = osmo_iofd_register(iofd, -1);
+	if (rc < 0) {
+		osmo_iofd_free(iofd);
+		target->tgt_file.wqueue->except_cb = NULL;
+		target->tgt_file.wqueue->bfd.fd = -1; /* Keep public field changes despite not used internally... */
+		talloc_free(target->tgt_file.wqueue);
+		return -EIO;
+	}
    return 0;
 }
@@ -235,8 +274,7 @@
  */
 int log_target_file_switch_to_wqueue(struct log_target *target)
 {
-	struct osmo_wqueue *wq;
-	int rc;
+	int rc, fd;
if (!target)
    	return -ENODEV;
@@ -246,35 +284,19 @@
    	return 1;
    }
-	/* we create a ~640kB sized talloc pool within the write-queue to ensure individual
-	 * log lines (stored as msgbs) will not put result in malloc() calls, and also to
-	 * reduce the OOM probability within logging, as the pool is already allocated */
-	wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,
-				  LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));
-	if (!wq)
-		return -ENOMEM;
-	osmo_wqueue_init(wq, LOG_WQUEUE_LEN);
-
    fflush(target->tgt_file.out);
-	if (target->type == LOG_TGT_TYPE_FILE) {
-		rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
-		if (rc < 0) {
-			talloc_free(wq);
-			return -errno;
-		}
-	} else {
-		rc = STDERR_FILENO;
-	}
-	wq->bfd.fd = rc;
-	wq->bfd.when = OSMO_FD_WRITE;
-	wq->write_cb = _file_wq_write_cb;
+	if (target->type == LOG_TGT_TYPE_FILE)
+		fd = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
+	else /* LOG_TGT_TYPE_STDERR: dup file so we can close it later with osmo_iofd_free() */
+		fd = dup(STDERR_FILENO);
-	rc = osmo_fd_register(&wq->bfd);
-	if (rc < 0) {
-		talloc_free(wq);
-		return -EIO;
-	}
-	target->tgt_file.wqueue = wq;
+	if (fd < 0)
+		return -errno;
+
+	rc = _log_target_file_setup_iofd(target, fd);
+	if (rc < 0)
+		return rc;
+
    target->raw_output = _file_raw_output;
    target->output = NULL;
@@ -293,45 +315,30 @@
 struct log_target *log_target_create_file(const char *fname)
 {
    struct log_target *target;
-	struct osmo_wqueue *wq;
-	int rc;
+	int rc, fd;
target = log_target_create();
    if (!target)
    	return NULL;
target->type = LOG_TGT_TYPE_FILE;
-	/* we create a ~640kB sized talloc pool within the write-queue to ensure individual
-	 * log lines (stored as msgbs) will not put result in malloc() calls, and also to
-	 * reduce the OOM probability within logging, as the pool is already allocated */
-	wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,
-				  LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));
-	if (!wq) {
-		log_target_destroy(target);
-		return NULL;
-	}
-	osmo_wqueue_init(wq, LOG_WQUEUE_LEN);
-	wq->bfd.fd = open(fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
-	if (wq->bfd.fd < 0) {
-		talloc_free(wq);
-		log_target_destroy(target);
-		return NULL;
-	}
-	wq->bfd.when = OSMO_FD_WRITE;
-	wq->write_cb = _file_wq_write_cb;
-
-	rc = osmo_fd_register(&wq->bfd);
-	if (rc < 0) {
-		talloc_free(wq);
-		log_target_destroy(target);
-		return NULL;
-	}
-
-	target->tgt_file.wqueue = wq;
-	target->raw_output = _file_raw_output;
    target->tgt_file.fname = talloc_strdup(target, fname);
+	OSMO_ASSERT(target->tgt_file.fname);
+	target->raw_output = _file_raw_output;
+
+	fd = open(fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
+	if (fd < 0)
+		goto free_ret;
+
+	rc = _log_target_file_setup_iofd(target, fd);
+	if (rc < 0)
+		goto free_ret;
return target;
+
+free_ret:
+	log_target_destroy(target);
+	return NULL;
 }
 #endif
diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c
index 3548b1d..27ad550 100644
--- a/tests/logging/logging_test.c
+++ b/tests/logging/logging_test.c
@@ -16,6 +16,7 @@
  */
#include <osmocom/core/logging.h>
+#include <osmocom/core/select.h>
 #include <osmocom/core/utils.h>
#include <stdlib.h>
@@ -138,5 +139,8 @@
    log_set_print_filename_pos(stderr_target, LOG_FILENAME_POS_LINE_END);
    DEBUGP(DLGLOBAL, "A message with source info printed last\n");
+	for (int i = 0; i < 20; i++)
+		osmo_select_main(1);
+
    return 0;
 }
diff --git a/tests/logging/logging_test.err b/tests/logging/logging_test.err
index 01ab878..fb5181c 100644
--- a/tests/logging/logging_test.err
+++ b/tests/logging/logging_test.err
@@ -7,5 +7,5 @@
 DLGLOBAL You should see this on DLGLOBAL (d)
 DLGLOBAL You should see this on DLGLOBAL (e)
 DLGLOBAL You should see this (DLGLOBAL on DEBUG)
-DLGLOBAL logging_test.c:137 A message with source info printed first
-DLGLOBAL A message with source info printed last (logging_test.c:139)
+DLGLOBAL logging_test.c:138 A message with source info printed first
+DLGLOBAL A message with source info printed last (logging_test.c:140)
-- 
To view, visit https://gerrit.osmocom.org/c/libosmocore/+/41925?usp=email
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings?usp=email

Gerrit-MessageType: merged
Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-Change-Id: Ieb6420246454ef59442b1fd7b1d14e2c00fa69a5
Gerrit-Change-Number: 41925
Gerrit-PatchSet: 17
Gerrit-Owner: pespin pespin@sysmocom.de
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: fixeria vyanitskiy@sysmocom.de
Gerrit-Reviewer: jolly andreas@eversberg.eu
Gerrit-Reviewer: laforge laforge@osmocom.org
Gerrit-Reviewer: osmith osmith@sysmocom.de
Gerrit-Reviewer: pespin pespin@sysmocom.de



    

2026

2025

2024

2023

2022

[L] Change in libosmocore[master]: Implement log file target using osmo_io