diff --git a/filter/data.c b/filter/data.c index f104d2f8..ce8d7561 100644 --- a/filter/data.c +++ b/filter/data.c @@ -598,7 +598,7 @@ val_format(const struct f_val *v, buffer *buf) char * val_format_str(struct linpool *lp, const struct f_val *v) { buffer b; - LOG_BUFFER_INIT(b); + STACK_BUFFER_INIT(b, 1024); val_format(v, &b); return lp_strdup(lp, b.start); } diff --git a/filter/f-inst.c b/filter/f-inst.c index caffc2b8..4d0974e9 100644 --- a/filter/f-inst.c +++ b/filter/f-inst.c @@ -656,15 +656,20 @@ VARARG; if (whati->varcount && !(fs->flags & FF_SILENT)) + { + if (!fs->buf.class) + log_prepare(&fs->buf, *L_INFO); + for (uint i=0; ivarcount; i++) - val_format(&(vv(i)), &fs->buf); + val_format(&(vv(i)), &fs->buf.buf); + } } INST(FI_FLUSH, 0, 0) { NEVER_CONSTANT; if (!(fs->flags & FF_SILENT)) /* After log_commit, the buffer is reset */ - log_commit(*L_INFO, &fs->buf); + log_commit(&fs->buf); } INST(FI_DIE, 0, 0) { diff --git a/filter/filter.c b/filter/filter.c index 0aff4d30..931bc85e 100644 --- a/filter/filter.c +++ b/filter/filter.c @@ -77,7 +77,7 @@ struct filter_state { struct rte *rte; /* Buffer for log output */ - struct buffer buf; + log_buffer buf; /* Filter execution flags */ int flags; @@ -219,8 +219,6 @@ f_run(const struct filter *filter, struct rte *rte, int flags) f_stack_init(filter_state); - LOG_BUFFER_INIT(filter_state.buf); - /* Run the interpreter itself */ enum filter_return fret = interpret(&filter_state, filter->root, NULL); @@ -256,8 +254,6 @@ f_eval_rte(const struct f_line *expr, struct rte *rte) f_stack_init(filter_state); - LOG_BUFFER_INIT(filter_state.buf); - ASSERT(!rta_is_cached(rte->attrs)); return interpret(&filter_state, expr, NULL); @@ -276,8 +272,6 @@ f_eval(const struct f_line *expr, struct f_val *pres) f_stack_init(filter_state); - LOG_BUFFER_INIT(filter_state.buf); - enum filter_return fret = interpret(&filter_state, expr, pres); return fret; } @@ -297,8 +291,6 @@ f_eval_int(const struct f_line *expr) struct f_val val; - LOG_BUFFER_INIT(filter_state.buf); - if (interpret(&filter_state, expr, &val) > F_RETURN) cf_error("Runtime error while evaluating expression; see log for details"); diff --git a/lib/birdlib.h b/lib/birdlib.h index 2eec5c0f..8146e63b 100644 --- a/lib/birdlib.h +++ b/lib/birdlib.h @@ -151,6 +151,16 @@ typedef struct buffer { byte *end; } buffer; +#define LOG_BUFFER_SIZE 2560 + +typedef struct log_buffer { + struct buffer buf; + byte *tm_pos; + byte *msg_pos; + int class; + char block[LOG_BUFFER_SIZE]; +} log_buffer; + #define STACK_BUFFER_INIT(buf,size) \ do { \ buf.start = alloca(size); \ @@ -158,13 +168,9 @@ typedef struct buffer { buf.end = buf.start + size; \ } while(0) -#define LOG_BUFFER_INIT(buf) \ - STACK_BUFFER_INIT(buf, LOG_BUFFER_SIZE) - -#define LOG_BUFFER_SIZE 1024 - #define log log_msg -void log_commit(int class, buffer *buf); +void log_prepare(log_buffer *buf, int class); +void log_commit(log_buffer *buf); void log_msg(const char *msg, ...); void log_rl(struct tbf *rl, const char *msg, ...); void die(const char *msg, ...) NORET; diff --git a/lib/timer.c b/lib/timer.c index 4e4aa55e..d64a3921 100644 --- a/lib/timer.c +++ b/lib/timer.c @@ -323,8 +323,5 @@ tm_format_real_time(char *x, size_t max, const char *fmt, btime t) if (!strfusec(tbuf, tbuf_size, fmt, t2)) return 0; - if (!strftime(x, max, tbuf, &tm)) - return 0; - - return 1; + return strftime(x, max, tbuf, &tm); } diff --git a/nest/cmds.c b/nest/cmds.c index 6717be0c..4805b5a2 100644 --- a/nest/cmds.c +++ b/nest/cmds.c @@ -134,7 +134,7 @@ void cmd_eval(const struct f_line *expr) { buffer buf; - LOG_BUFFER_INIT(buf); + STACK_BUFFER_INIT(buf, CLI_MSG_SIZE); if (f_eval_buf(expr, &buf) > F_RETURN) { diff --git a/proto/bgp/bgp.c b/proto/bgp/bgp.c index c98f84ab..3a7ed6b7 100644 --- a/proto/bgp/bgp.c +++ b/proto/bgp/bgp.c @@ -2532,7 +2532,7 @@ static void bgp_show_afis(int code, char *s, u32 *afis, uint count) { buffer b; - LOG_BUFFER_INIT(b); + STACK_BUFFER_INIT(b, CLI_MSG_SIZE); buffer_puts(&b, s); diff --git a/sysdep/unix/config.Y b/sysdep/unix/config.Y index a50ec757..b1d60906 100644 --- a/sysdep/unix/config.Y +++ b/sysdep/unix/config.Y @@ -52,15 +52,14 @@ log_file: text log_limit { if (!parse_and_exit) { - this_log->rf = rf_open(new_config->pool, $1, "a"); + this_log->rf = rf_open(new_config->pool, $1, RF_APPEND); if (!this_log->rf) cf_error("Unable to open log file '%s': %m", $1); - this_log->fh = rf_file(this_log->rf); } this_log->pos = -1; this_log->filename = $1; } - | SYSLOG syslog_name { this_log->fh = NULL; new_config->syslog_name = $2; } - | STDERR { this_log->fh = stderr; } + | SYSLOG syslog_name { this_log->rf = NULL; new_config->syslog_name = $2; } + | STDERR { this_log->rf = &rf_stderr; } ; log_mask: @@ -93,7 +92,7 @@ mrtdump_base: | MRTDUMP text ';' { if (!parse_and_exit) { - struct rfile *f = rf_open(new_config->pool, $2, "a"); + struct rfile *f = rf_open(new_config->pool, $2, RF_APPEND); if (!f) cf_error("Unable to open MRTDump file '%s': %m", $2); new_config->mrtdump_file = rf_fileno(f); } diff --git a/sysdep/unix/io.c b/sysdep/unix/io.c index b21df057..74f3fc71 100644 --- a/sysdep/unix/io.c +++ b/sysdep/unix/io.c @@ -64,7 +64,11 @@ struct rfile { resource r; - FILE *f; + int fd; +}; + +struct rfile rf_stderr = { + .fd = 2, }; static void @@ -72,7 +76,7 @@ rf_free(resource *r) { struct rfile *a = (struct rfile *) r; - fclose(a->f); + close(a->fd); } static void @@ -80,7 +84,7 @@ rf_dump(resource *r, unsigned indent UNUSED) { struct rfile *a = (struct rfile *) r; - debug("(FILE *%p)\n", a->f); + debug("(fd %d)\n", a->fd); } static struct resclass rf_class = { @@ -93,28 +97,34 @@ static struct resclass rf_class = { }; struct rfile * -rf_open(pool *p, const char *name, const char *mode) +rf_open(pool *p, const char *name, enum rf_mode mode) { - FILE *f = fopen(name, mode); + int omode = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH | S_IWOTH; + int flags; - if (!f) - return NULL; + switch (mode) + { + case RF_APPEND: + flags = O_WRONLY | O_CREAT | O_APPEND; + break; + + default: + bug("rf_open() must have the mode set"); + } + + int fd = open(name, flags, omode); + if (fd < 0) + return NULL; /* The caller takes care of printing %m. */ struct rfile *r = ralloc(p, &rf_class); - r->f = f; + r->fd = fd; return r; } -void * -rf_file(struct rfile *f) -{ - return f->f; -} - int rf_fileno(struct rfile *f) { - return fileno(f->f); + return f->fd; } diff --git a/sysdep/unix/log.c b/sysdep/unix/log.c index 5a1241dc..b5159914 100644 --- a/sysdep/unix/log.c +++ b/sysdep/unix/log.c @@ -32,8 +32,7 @@ #include "lib/lists.h" #include "sysdep/unix/unix.h" -static int dbg_fd = -1; -static FILE *dbgf; +static struct rfile *dbg_rf; static list *current_log_list; static char *current_syslog_name; /* NULL -> syslog closed */ @@ -46,6 +45,12 @@ static pthread_mutex_t log_mutex; static inline void log_lock(void) { pthread_mutex_lock(&log_mutex); } static inline void log_unlock(void) { pthread_mutex_unlock(&log_mutex); } +/* Logging flags to validly prepare logging messages */ +#define LOGGING_TO_TERMINAL 0x1 +#define LOGGING_TO_FILE 0x2 + +static _Atomic uint logging_flags; + #ifdef HAVE_SYSLOG_H #include @@ -86,15 +91,16 @@ log_size(struct log_config *l) static void log_close(struct log_config *l) { - rfree(l->rf); + if (l->rf != &rf_stderr) + rfree(l->rf); + l->rf = NULL; - l->fh = NULL; } static int log_open(struct log_config *l) { - l->rf = rf_open(config->pool, l->filename, "a"); + l->rf = rf_open(config->pool, l->filename, RF_APPEND); if (!l->rf) { /* Well, we cannot do much in case of error as log is closed */ @@ -102,7 +108,6 @@ log_open(struct log_config *l) return -1; } - l->fh = rf_file(l->rf); l->pos = log_size(l); return 0; @@ -125,6 +130,8 @@ log_rotate(struct log_config *l) return log_open(l); } +#define LOG_MSG_OFFSET (TM_DATETIME_BUFFER_SIZE + 64) + /** * log_commit - commit a log message * @class: message class information (%L_DEBUG to %L_BUG, see |lib/birdlib.h|) @@ -139,69 +146,83 @@ log_rotate(struct log_config *l) * in log(), so it should be written like *L_INFO. */ void -log_commit(int class, buffer *buf) +log_commit(log_buffer *buf) { struct log_config *l; - if (buf->pos == buf->end) - strcpy(buf->end - 100, " ... "); + if (buf->buf.pos == buf->buf.end) +#define TOO_LONG " ... " + memcpy(buf->buf.end - sizeof TOO_LONG, TOO_LONG, sizeof TOO_LONG); +#undef TOO_LONG log_lock(); WALK_LIST(l, *current_log_list) { - if (!(l->mask & (1 << class))) + if (!(l->mask & (1 << buf->class))) continue; - if (l->fh) + if (l->rf && buf->tm_pos) { - if (l->terminal_flag) - fputs("bird: ", l->fh); - else - { - byte tbuf[TM_DATETIME_BUFFER_SIZE]; - const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f"; - if (!tm_format_real_time(tbuf, sizeof(tbuf), fmt, current_real_time())) - strcpy(tbuf, ""); + *buf->buf.pos = '\n'; + byte *begin = l->terminal_flag ? buf->buf.start : buf->tm_pos; + off_t msg_len = buf->buf.pos - begin + 1; + if (l->limit && (l->pos + msg_len > l->limit) && (log_rotate(l) < 0)) + continue; - if (l->limit) - { - off_t msg_len = strlen(tbuf) + strlen(class_names[class]) + - (buf->pos - buf->start) + 5; - - if (l->pos < 0) - l->pos = log_size(l); - - if (l->pos + msg_len > l->limit) - if (log_rotate(l) < 0) - continue; - - l->pos += msg_len; - } - - fprintf(l->fh, "%s [%04x] <%s> ", tbuf, THIS_THREAD_ID, class_names[class]); - } - fputs(buf->start, l->fh); - fputc('\n', l->fh); - fflush(l->fh); + l->pos += msg_len; + while ((write(rf_fileno(l->rf), buf->tm_pos, msg_len) < 0) && (errno == EINTR)) + ; } #ifdef HAVE_SYSLOG_H else - syslog(syslog_priorities[class], "%s", buf->start); + { + *buf->buf.pos = '\0'; + syslog(syslog_priorities[buf->class], "%s", buf->msg_pos); + } #endif } log_unlock(); - buf->pos = buf->start; + buf->msg_pos = buf->tm_pos = NULL; } int buffer_vprint(buffer *buf, const char *fmt, va_list args); +void +log_prepare(log_buffer *buf, int class) +{ + buf->buf.start = buf->buf.pos = buf->block; + buf->buf.end = buf->block + sizeof buf->block; + + int lf = atomic_load_explicit(&logging_flags, memory_order_acquire); + if (lf & LOGGING_TO_TERMINAL) + buffer_puts(&buf->buf, "bird: "); + + if (lf & LOGGING_TO_FILE) + { + const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f"; + + buf->tm_pos = buf->buf.pos; + int t = tm_format_real_time(buf->buf.pos, buf->buf.end - buf->buf.pos, fmt, current_real_time()); + if (t) + buf->buf.pos += t; + else + buffer_puts(&buf->buf, "