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 <[email protected]>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: fixeria <[email protected]>
Gerrit-Reviewer: jolly <[email protected]>
Gerrit-Reviewer: laforge <[email protected]>
Gerrit-Reviewer: osmith <[email protected]>
Gerrit-Reviewer: pespin <[email protected]>
