mirrors/bird
mirrors/bird
0
0
Fork 0
mirror of https://gitlab.nic.cz/labs/bird.git synced 2024-12-22 09:41:54 +00:00
Code Releases Activity

Logging: Abolished stdio in favor of write() to make the logging faster.

Browse Source
This commit is contained in:
Maria Matejka 2023-08-16 15:05:36 +02:00
parent 6728e01e6f
commit a6a8cbe415
12 changed files with 157 additions and 138 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
filter/data.c
View File

@ -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);
}

9
filter/f-inst.c
View File

@ -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; i<whati->varcount; 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) {

10
filter/filter.c
View File

@ -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");

18
lib/birdlib.h
View File

@ -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;

5
lib/timer.c
View File

@ -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);
}

2
nest/cmds.c
View File

@ -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)
{

2
proto/bgp/bgp.c
View File

@ -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);

9
sysdep/unix/config.Y
View File

@ -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);
}

40
sysdep/unix/io.c
View File

@ -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;
}

179
sysdep/unix/log.c
View File

@ -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 <sys/syslog.h>
@ -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, " ... <too long>");
if (buf->buf.pos == buf->buf.end)
#define TOO_LONG " ... <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, "<error>");
*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, "<time format error>");
buffer_print(&buf->buf, " [%04x] <%s> ", THIS_THREAD_ID, class_names[class]);
}
buf->msg_pos = buf->buf.pos;
buf->class = class;
}
static void
vlog(int class, const char *msg, va_list args)
{
buffer buf;
LOG_BUFFER_INIT(buf);
buffer_vprint(&buf, msg, args);
log_commit(class, &buf);
static _Thread_local log_buffer buf;
log_prepare(&buf, class);
buffer_vprint(&buf.buf, msg, args);
log_commit(&buf);
}
@ -301,33 +322,13 @@ debug(const char *msg, ...)
int max = MAX_DEBUG_BUFSIZE;
va_start(args, msg);
if (dbgf)
if (dbg_rf)
{
#if 0
struct timespec dbg_time;
clock_gettime(CLOCK_MONOTONIC, &dbg_time);
uint nsec;
uint sec;
if (dbg_time.tv_nsec > dbg_time_start.tv_nsec)
{
nsec = dbg_time.tv_nsec - dbg_time_start.tv_nsec;
sec = dbg_time.tv_sec - dbg_time_start.tv_sec;
}
else
{
nsec = 1000000000 + dbg_time.tv_nsec - dbg_time_start.tv_nsec;
sec = dbg_time.tv_sec - dbg_time_start.tv_sec - 1;
}
int n = bsnprintf(pos, max, "%u.%09u: [%04x] ", sec, nsec, THIS_THREAD_ID);
pos += n;
max -= n;
#endif
if (bvsnprintf(pos, max, msg, args) < 0)
int s = bvsnprintf(pos, max, msg, args);
if (s < 0)
bug("Extremely long debug output, split it.");
fputs(buf, dbgf);
write(rf_fileno(dbg_rf), buf, s);
}
va_end(args);
}
@ -343,8 +344,8 @@ debug(const char *msg, ...)
void
debug_safe(const char *msg)
{
if (dbg_fd >= 0)
write(dbg_fd, msg, strlen(msg));
if (dbg_rf)
write(rf_fileno(dbg_rf), msg, strlen(msg));
}
static list *
@ -355,7 +356,7 @@ default_log_list(int initial, const char **syslog_name)
*syslog_name = NULL;
#ifdef HAVE_SYSLOG_H
if (!dbgf)
if (!dbg_rf)
{
static struct log_config lc_syslog;
lc_syslog = (struct log_config){
@ -367,24 +368,24 @@ default_log_list(int initial, const char **syslog_name)
}
#endif
if (dbgf && (dbgf != stderr))
if (dbg_rf && (dbg_rf != &rf_stderr))
{
static struct log_config lc_debug;
lc_debug = (struct log_config){
.mask = ~0,
.fh = dbgf
.rf = dbg_rf,
};
add_tail(&log_list, &lc_debug.n);
}
if (initial || (dbgf == stderr))
if (initial || (dbg_rf == &rf_stderr))
{
static struct log_config lc_stderr;
lc_stderr = (struct log_config){
.mask = ~0,
.terminal_flag = 1,
.fh = stderr
.rf = &rf_stderr,
};
add_tail(&log_list, &lc_stderr.n);
@ -411,10 +412,19 @@ log_switch(int initial, list *logs, const char *new_syslog_name)
log_close(l);
/* Reopen the logs, needed for 'configure undo' */
uint flags = 0;
if (logs)
WALK_LIST(l, *logs)
{
if (l->terminal_flag)
flags |= LOGGING_TO_TERMINAL;
if (l->filename && !l->rf)
log_open(l);
if (l->rf)
flags |= LOGGING_TO_FILE;
}
atomic_store_explicit(&logging_flags, flags, memory_order_release);
current_log_list = logs;
@ -447,24 +457,17 @@ log_init_debug(char *f)
{
clock_gettime(CLOCK_MONOTONIC, &dbg_time_start);
dbg_fd = -1;
if (dbgf && dbgf != stderr)
fclose(dbgf);
if (dbg_rf && dbg_rf != &rf_stderr)
close(rf_fileno(dbg_rf));
if (!f)
dbgf = NULL;
dbg_rf = NULL;
else if (!*f)
dbgf = stderr;
else if (!(dbgf = fopen(f, "a")))
dbg_rf = &rf_stderr;
else if (!(dbg_rf = rf_open(&root_pool, f, RF_APPEND)))
{
/* Cannot use die() nor log() here, logging is not yet initialized */
fprintf(stderr, "bird: Unable to open debug file %s: %s\n", f, strerror(errno));
exit(1);
}
if (dbgf)
{
setvbuf(dbgf, NULL, _IONBF, 0);
dbg_fd = fileno(dbgf);
}
}

5
sysdep/unix/main.c
View File

@ -202,9 +202,10 @@ sysdep_preconfig(struct config *c)
int
sysdep_commit(struct config *new, struct config *old)
{
log_switch(0, &new->logfiles, new->syslog_name);
bird_thread_commit(new, old);
if (!new->shutdown)
log_switch(0, &new->logfiles, new->syslog_name);
bird_thread_commit(new, old);
return 0;
}

14
sysdep/unix/unix.h
View File

@ -114,9 +114,16 @@ void io_init(void);
void io_loop(void);
void io_log_dump(void);
int sk_open_unix(struct birdsock *s, struct birdloop *, char *name);
struct rfile *rf_open(struct pool *, const char *name, const char *mode);
void *rf_file(struct rfile *f);
enum rf_mode {
RF_APPEND,
};
struct rfile *rf_open(struct pool *, const char *name, enum rf_mode mode);
int rf_fileno(struct rfile *f);
extern struct rfile rf_stderr;
void test_old_bird(char *path);
/* krt.c bits */
@ -131,8 +138,7 @@ void log_switch(int initial, list *l, const char *);
struct log_config {
node n;
uint mask; /* Classes to log */
void *fh; /* FILE to log to, NULL=syslog */
struct rfile *rf; /* Resource for log file */
struct rfile *rf; /* Resource for log file; NULL=syslog */
const char *filename; /* Log filename */
const char *backup; /* Secondary filename (for log rotation) */
off_t pos; /* Position/size of current log */