pespin has uploaded this change for review. (
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
TODO: re-add talloc_pool.
Related: OS#6918
Change-Id: Ieb6420246454ef59442b1fd7b1d14e2c00fa69a5
---
M include/osmocom/core/logging_internal.h
M src/core/logging_file.c
M src/vty/logging_vty.c
M tests/logging/logging_test.c
M tests/logging/logging_test.err
5 files changed, 112 insertions(+), 145 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/25/41925/1
diff --git a/include/osmocom/core/logging_internal.h
b/include/osmocom/core/logging_internal.h
index cadd4df..187a7df 100644
--- a/include/osmocom/core/logging_internal.h
+++ b/include/osmocom/core/logging_internal.h
@@ -9,6 +9,7 @@
#include <osmocom/core/utils.h>
#include <osmocom/core/linuxlist.h>
#include <osmocom/core/logging.h>
+#include <osmocom/core/osmo_io.h>
/* maximum length of the log string of a single log event (typically line) */
#define MAX_LOG_SIZE 4096
@@ -52,8 +53,8 @@
/* direct, blocking output via stdio */
FILE *out;
const char *fname;
- /* indirect output via write_queue and
osmo_select_main() */
- struct osmo_wqueue *wqueue;
+ /* indirect output via iofd and osmo_select_main() */
+ struct osmo_io_fd *iofd;
} tgt_file;
struct {
diff --git a/src/core/logging_file.c b/src/core/logging_file.c
index 1a5bdb2..d859dab 100644
--- a/src/core/logging_file.c
+++ b/src/core/logging_file.c
@@ -37,44 +37,52 @@
#include <osmocom/core/talloc.h>
#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
-
/*! 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;
int rc;
- OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE || target->type ==
LOG_TGT_TYPE_STDERR);
- OSMO_ASSERT(target->tgt_file.out || target->tgt_file.wqueue);
+ OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE ||
+ target->type == LOG_TGT_TYPE_STDERR);
+ OSMO_ASSERT(target->tgt_file.out || target->tgt_file.iofd);
- if (target->tgt_file.out) {
- fclose(target->tgt_file.out);
- target->tgt_file.out = fopen(target->tgt_file.fname, "a");
- if (!target->tgt_file.out)
- return -errno;
- } else {
- wq = target->tgt_file.wqueue;
- if (wq->bfd.fd >= 0) {
- osmo_fd_unregister(&wq->bfd);
- close(wq->bfd.fd);
- wq->bfd.fd = -1;
+ if (target->type == LOG_TGT_TYPE_STDERR)
+ return -ENOTSUP;
+
+ switch (target->type) {
+ case LOG_TGT_TYPE_STDERR:
+ return -ENOTSUP;
+ case LOG_TGT_TYPE_FILE:
+ if (target->tgt_file.out) { /* stream mode */
+ fclose(target->tgt_file.out);
+ target->tgt_file.out = fopen(target->tgt_file.fname,
"a");
+ if (!target->tgt_file.out)
+ return -errno;
+ return 0;
}
+ osmo_iofd_close(target->tgt_file.iofd);
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(target->tgt_file.iofd, rc);
+ if (rc < 0) {
+ osmo_iofd_free(target->tgt_file.iofd);
+ target->tgt_file.iofd = NULL;
+ return -EIO;
+ }
+ break;
+ default:
+ OSMO_ASSERT(0);
}
return 0;
@@ -87,7 +95,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);
@@ -97,38 +104,20 @@
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.iofd) {
+ osmo_iofd_free(target->tgt_file.iofd);
+ target->tgt_file.iofd = NULL;
}
+
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,
@@ -146,8 +135,8 @@
struct msgb *msg;
int rc;
- OSMO_ASSERT(target->tgt_file.wqueue);
- msg = msgb_alloc_c(target->tgt_file.wqueue, MAX_LOG_SIZE,
"log_file_msg");
+ OSMO_ASSERT(target->tgt_file.iofd);
+ msg = msgb_alloc_c(target->tgt_file.iofd, MAX_LOG_SIZE, "log_file_msg");
if (!msg)
return;
@@ -157,18 +146,8 @@
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(target->tgt_file.iofd, msg);
+ if (rc < 0) {
msgb_free(msg);
/* TODO: increment some counter so we can see that messages
were dropped */
}
@@ -181,7 +160,7 @@
*/
int log_target_file_switch_to_stream(struct log_target *target)
{
- struct osmo_wqueue *wq;
+ unsigned int prev_queue_len;
if (!target)
return -ENODEV;
@@ -191,37 +170,28 @@
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);
- }
+ prev_queue_len = osmo_iofd_txqueue_len(target->tgt_file.iofd);
- /* now that everything succeeded, we can finally close the old output
fd */
- if (target->type == LOG_TGT_TYPE_FILE) {
- osmo_fd_unregister(&wq->bfd);
- close(wq->bfd.fd);
- wq->bfd.fd = -1;
- }
-
- /* release the queue itself */
- talloc_free(wq);
- target->tgt_file.wqueue = NULL;
+ /* now that everything succeeded, we can finally close the old iofd */
+ osmo_iofd_free(target->tgt_file.iofd);
+ target->tgt_file.iofd = 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;
}
@@ -232,8 +202,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;
@@ -243,35 +212,33 @@
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);
+ if (fd < 0)
+ return -errno;
+
+ target->tgt_file.iofd = osmo_iofd_setup(target, fd,
target->tgt_file.fname,
+ OSMO_IO_FD_MODE_READ_WRITE,
+ &log_target_file_io_ops,
target);
+ if (!target->tgt_file.iofd) {
+ if (target->type == LOG_TGT_TYPE_FILE)
+ close(fd);
return -EIO;
}
- target->tgt_file.wqueue = wq;
+
+ osmo_iofd_set_txqueue_max_length(target->tgt_file.iofd, LOG_WQUEUE_LEN);
+
+ rc = osmo_iofd_register(target->tgt_file.iofd, -1);
+ if (rc < 0) {
+ osmo_iofd_free(target->tgt_file.iofd);
+ target->tgt_file.iofd = NULL;
+ return -EIO;
+ }
+
target->raw_output = _file_raw_output;
target->output = NULL;
@@ -290,45 +257,40 @@
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;
+
+ target->tgt_file.iofd = osmo_iofd_setup(target, fd,
target->tgt_file.fname,
+ OSMO_IO_FD_MODE_READ_WRITE,
+ &log_target_file_io_ops,
target);
+ if (!target->tgt_file.iofd) {
+ close(fd);
+ goto free_ret;
+ }
+
+ osmo_iofd_set_txqueue_max_length(target->tgt_file.iofd, LOG_WQUEUE_LEN);
+
+ rc = osmo_iofd_register(target->tgt_file.iofd, -1);
+ if (rc < 0)
+ goto free_ret;
return target;
+
+free_ret:
+ log_target_destroy(target);
+ return NULL;
}
#endif
diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c
index 6fd7abc..8e10582 100644
--- a/src/vty/logging_vty.c
+++ b/src/vty/logging_vty.c
@@ -1043,7 +1043,7 @@
return 1;
break;
case LOG_TGT_TYPE_STDERR:
- if (tgt->tgt_file.wqueue)
+ if (tgt->tgt_file.iofd)
vty_out(vty, "log stderr%s", VTY_NEWLINE);
else
vty_out(vty, "log stderr blocking-io%s", VTY_NEWLINE);
@@ -1057,7 +1057,7 @@
#endif
break;
case LOG_TGT_TYPE_FILE:
- if (tgt->tgt_file.wqueue)
+ if (tgt->tgt_file.iofd)
vty_out(vty, "log file %s%s", tgt->tgt_file.fname,
VTY_NEWLINE);
else
vty_out(vty, "log file %s blocking-io%s",
tgt->tgt_file.fname, VTY_NEWLINE);
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: newchange
Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-Change-Id: Ieb6420246454ef59442b1fd7b1d14e2c00fa69a5
Gerrit-Change-Number: 41925
Gerrit-PatchSet: 1
Gerrit-Owner: pespin <[email protected]>
