#include "conf/conf.h"
#include "lib/string.h"
#include "lib/lists.h"
+ #include "lib/socket.h"
#include "sysdep/unix/unix.h"
+#include "sysdep/unix/io-loop.h"
-static int dbg_fd = -1;
-static FILE *dbgf;
-static list *current_log_list;
-static char *current_syslog_name; /* NULL -> syslog closed */
+static pool *log_pool;
+static struct rfile *dbg_rf;
+static char *current_syslog_name = NULL; /* NULL -> syslog closed */
-#ifdef USE_PTHREADS
+_Atomic uint max_thread_id = 1;
+_Thread_local uint this_thread_id;
#include <pthread.h>
"BUG"
};
-static inline off_t
-log_size(struct log_config *l)
-{
- struct stat st;
- return (!fstat(rf_fileno(l->rf), &st) && S_ISREG(st.st_mode)) ? st.st_size : 0;
-}
+struct log_channel {
+ struct log_channel * _Atomic next;
+ const char *filename; /* Log filename */
+ const char *backup; /* Secondary filename (for log rotation) */
+ struct rfile * _Atomic rf; /* File handle */
+ off_t limit; /* Log size limit */
+ _Atomic uint mask; /* Classes to log */
+ uint new_mask; /* Pending new mask */
+ uint prepare; /* Which message parts to prepare */
++ const char *udp_host; /* UDP log dst host name */
++ ip_addr udp_ip; /* UDP log dst IP address */
++ uint udp_port; /* UDP log dst port */
++ sock * _Atomic udp_sk; /* UDP socket */
+};
+
+struct log_thread_syncer {
+ struct bird_thread_syncer sync;
+ struct log_channel *lc_close;
+ struct rfile *rf_close;
++ sock *sk_close;
+ const char *name;
+ event lts_event;
+};
static void
-log_close(struct log_config *l)
+lts_done(struct bird_thread_syncer *sync)
{
- rfree(l->rf);
- l->rf = NULL;
- l->fh = NULL;
-}
+ struct log_thread_syncer *lts = SKIP_BACK(struct log_thread_syncer, sync, sync);
-static int
-log_open(struct log_config *l)
-{
- l->rf = rf_open(config->pool, l->filename, "a");
- if (!l->rf)
+ log_lock();
+ if (lts->lc_close)
{
- /* Well, we cannot do much in case of error as log is closed */
- l->mask = 0;
- return -1;
+ lts->rf_close = atomic_load_explicit(<s->lc_close->rf, memory_order_relaxed);
++ lts->sk_close = atomic_load_explicit(<s->lc_close->udp_sk, memory_order_relaxed);
+ mb_free(lts->lc_close);
}
- l->fh = rf_file(l->rf);
- l->pos = log_size(l);
+ if (lts->rf_close && lts->rf_close != &rf_stderr)
+ rfree(lts->rf_close);
+
++ if (lts->sk_close)
++ rfree(lts->sk_close);
+
- return 0;
+ mb_free(lts);
+ log_unlock();
}
-static int
-log_rotate(struct log_config *l)
+static void
+lts_event(void *_lts)
{
- log_close(l);
-
- /* If we cannot rename the logfile, we at least try to delete it
- in order to continue logging and not exceeding logfile size */
- if ((rename(l->filename, l->backup) < 0) &&
- (unlink(l->filename) < 0))
- {
- l->mask = 0;
- return -1;
- }
-
- return log_open(l);
+ struct log_thread_syncer *lts = _lts;
+ bird_thread_sync_all(<s->sync, NULL, lts_done, lts->name);
}
-/* Expected to be called during config parsing */
-int
-log_open_udp(struct log_config *l, pool *p)
+static void
+lts_request(struct log_channel *lc_close, struct rfile *rf_close, const char *name)
{
- ASSERT(l->host || ipa_nonzero(l->ip));
-
- if (l->host && ipa_zero(l->ip))
- {
- const char *err_msg;
- l->ip = resolve_hostname(l->host, SK_UDP, &err_msg);
-
- if (ipa_zero(l->ip))
- {
- cf_warn("Cannot resolve hostname '%s': %s", l->host, err_msg);
- goto err0;
- }
- }
-
- sock *sk = sk_new(p);
- sk->type = SK_UDP;
- sk->daddr = l->ip;
- sk->dport = l->port;
- sk->flags = SKF_CONNECT | SKF_THREAD;
-
- if (sk_open(sk) < 0)
- {
- cf_warn("Cannot open UDP log socket: %s%#m", sk->err);
- goto err1;
- }
-
- /* Move fd from sk resource to rf resource */
- l->rf = rf_fdopen(p, sk->fd, "a");
- if (!l->rf)
- goto err1;
+ struct log_thread_syncer *lts = mb_allocz(log_pool, sizeof *lts);
+ lts->lc_close = lc_close;
+ lts->rf_close = rf_close;
+ lts->name = name;
+ lts->lts_event = (event) { .hook = lts_event, .data = lts, };
+ ev_send_loop(&main_birdloop, <s->lts_event);
+}
- l->fh = rf_file(l->rf);
+static void
+log_rotate(struct log_channel *lc)
+{
+ struct log_thread_syncer *lts = mb_allocz(log_pool, sizeof *lts);
- sk->fd = -1;
- rfree(sk);
+ if ((rename(lc->filename, lc->backup) < 0) && (unlink(lc->filename) < 0))
+ return lts_request(lc, NULL, "Log Rotate Failed");
- return 0;
+ struct rfile *rf = rf_open(log_pool, lc->filename, RF_APPEND, lc->limit);
+ if (!rf)
+ return lts_request(lc, NULL, "Log Rotate Failed");
-err1:
- rfree(sk);
-err0:
- l->mask = 0;
- return -1;
+ lts_request(NULL, atomic_load_explicit(&lc->rf, memory_order_relaxed), "Log Rotate Close Old File");
+ atomic_store_explicit(&lc->rf, rf, memory_order_release);
}
- #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|)
* 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>");
-
- log_lock();
- WALK_LIST(l, *current_log_list)
+ /* Store the last pointer */
+ buf->pos[LBP__MAX] = buf->buf.pos;
+
+ /* Append the too-long message if 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
+
+ for (
+ struct log_channel *l = atomic_load_explicit(&global_logs, memory_order_acquire);
+ l;
+ l = atomic_load_explicit(&l->next, memory_order_acquire)
+ )
{
- if (!(l->mask & (1 << class)))
+ uint mask = atomic_load_explicit(&l->mask, memory_order_acquire);
+ if (!(mask & (1 << buf->class)))
continue;
- if (l->fh)
+
+ struct rfile *rf = atomic_load_explicit(&l->rf, memory_order_acquire);
- if (rf)
++ sock *sk = atomic_load_explicit(&l->udp_sk, memory_order_acquire);
++
++ if (rf || sk)
{
- if (l->terminal_flag)
- fputs("bird: ", l->fh);
- else if (l->udp_flag)
+ /* Construct the iovec */
+ static char terminal_prefix[] = "bird: ",
+ newline[] = "\n";
+ STATIC_ASSERT(sizeof newline == 2);
+
+ struct iovec iov[LBP__MAX+2];
+ uint iov_count = 0;
+ if (BIT32_TEST(&l->prepare, LBPP_TERMINAL))
+ iov[iov_count++] = (struct iovec) {
+ .iov_base = terminal_prefix,
+ .iov_len = sizeof terminal_prefix - 1,
+ };
+
+ for (uint p = 0; p < LBP__MAX; p++)
+ if (BIT32_TEST(&l->prepare, p))
{
- int pri = LOG_DAEMON | syslog_priorities[class];
- char tbuf[TM_DATETIME_BUFFER_SIZE];
- const char *hostname = (config && config->hostname) ? config->hostname : "<none>";
- const char *fmt = "%b %d %T.%6f";
- if (!tm_format_real_time(tbuf, sizeof(tbuf), fmt, current_real_time()))
- strcpy(tbuf, "<error>");
-
- /* Legacy RFC 3164 format, but with us precision */
- fprintf(l->fh, "<%d>%s %s %s: ", pri, tbuf, hostname, bird_name);
+ off_t sz = buf->pos[p+1] - buf->pos[p];
+ if (sz > 0)
+ iov[iov_count++] = (struct iovec) {
+ .iov_base = buf->pos[p],
+ .iov_len = sz,
+ };
}
- 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>");
- iov[iov_count++] = (struct iovec) {
- .iov_base = newline,
- .iov_len = sizeof newline - 1,
- };
- if (l->limit)
- {
- off_t msg_len = strlen(tbuf) + strlen(class_names[class]) +
- (buf->pos - buf->start) + 5;
++ if (rf)
++ {
++ iov[iov_count++] = (struct iovec) {
++ .iov_base = newline,
++ .iov_len = sizeof newline - 1,
++ };
- do {
- if (rf_writev(rf, iov, iov_count))
- break;
- if (l->pos < 0)
- l->pos = log_size(l);
++ do {
++ if (rf_writev(rf, iov, iov_count))
++ break;
- log_lock();
- rf = atomic_load_explicit(&l->rf, memory_order_acquire);
- if (rf_writev(rf, iov, iov_count))
- {
- log_unlock();
- break;
- }
- if (l->pos + msg_len > l->limit)
- if (log_rotate(l) < 0)
- continue;
-
- l->pos += msg_len;
++ log_lock();
++ rf = atomic_load_explicit(&l->rf, memory_order_acquire);
++ if (rf_writev(rf, iov, iov_count))
++ {
++ log_unlock();
++ break;
+ }
- log_rotate(l);
- log_unlock();
- fprintf(l->fh, "%s <%s> ", tbuf, class_names[class]);
- }
- fputs(buf->start, l->fh);
- fputc('\n', l->fh);
- fflush(l->fh);
++ log_rotate(l);
++ log_unlock();
+
- rf = atomic_load_explicit(&l->rf, memory_order_relaxed);
- } while (!rf_writev(rf, iov, iov_count));
++ rf = atomic_load_explicit(&l->rf, memory_order_relaxed);
++ } while (!rf_writev(rf, iov, iov_count));
++ }
++ else if (sk)
++ {
++ while ((writev(sk->fd, iov, iov_count) < 0) && (errno == EINTR))
++ ;
++ /* FIXME: Silently ignoring write errors */
++ }
}
#ifdef HAVE_SYSLOG_H
else
int buffer_vprint(buffer *buf, const char *fmt, va_list args);
+void
+log_prepare(log_buffer *buf, int class)
+{
+ buf->class = 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);
+
+ buf->pos[LBP_TIMESTAMP] = buf->buf.pos;
+ if (BIT32_TEST(&lf, LBP_TIMESTAMP))
+ {
+ const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f";
+ 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>");
+
+ *(buf->buf.pos++) = ' ';
+ }
+
++ buf->pos[LBP_UDP_HEADER] = buf->buf.pos;
++ if (BIT32_TEST(&lf, LBP_UDP_HEADER))
++ {
++ /* Legacy RFC 3164 format, but with us precision */
++ buffer_print(&buf->buf, "<%d>", LOG_DAEMON | syslog_priorities[class]);
++
++ const char *fmt = "%b %d %T.%6f";
++ 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>");
++
++ const char *hostname = (config && config->hostname) ? config->hostname : "<none>";
++ buffer_print(&buf->buf, " %s %s: ", hostname, bird_name);
++ }
++
+ buf->pos[LBP_THREAD_ID] = buf->buf.pos;
+ if (BIT32_TEST(&lf, LBP_THREAD_ID))
+ buffer_print(&buf->buf, "[%04x] ", THIS_THREAD_ID);
+
+ buf->pos[LBP_CLASS] = buf->buf.pos;
+ if (BIT32_TEST(&lf, LBP_CLASS))
+ buffer_print(&buf->buf, "<%s> ", class_names[class]);
+
+ buf->pos[LBP_MSG] = buf->buf.pos;
+}
+
static void
vlog(int class, const char *msg, va_list args)
{
return &log_list;
}
++
void
log_switch(int initial, list *logs, const char *new_syslog_name)
{
if (!logs || EMPTY_LIST(*logs))
logs = default_log_list(initial, &new_syslog_name);
- /* Close the logs to avoid pinning them on disk when deleted */
- if (current_log_list)
- WALK_LIST(l, *current_log_list)
- if (l->filename && l->rf)
- log_close(l);
+ ASSERT_DIE(logs);
- /* Reopen the logs, needed for 'configure undo' */
- if (logs)
- WALK_LIST(l, *logs)
- if (l->filename && !l->rf)
- log_open(l);
+ /* Prepare the new log configuration */
+ struct log_config *l;
+ WALK_LIST(l, *logs)
+ {
+ int erf = 0;
+ log_lock();
+ if (l->rf && (l->rf != &rf_stderr))
+ rmove(l->rf, log_pool);
+ else if (l->filename)
+ {
+ l->rf = rf_open(log_pool, l->filename, RF_APPEND, l->limit);
+ erf = l->rf ? 0 : errno;
+ }
+ log_unlock();
+ if (erf)
+ log(L_ERR "Failed to open log file '%s': %M", l->filename, erf);
+ }
- current_log_list = logs;
+ uint total_mask = 0;
+ uint flags = 0;
-#ifdef HAVE_SYSLOG_H
- if (!bstrcmp(current_syslog_name, new_syslog_name))
- goto done;
+ /* Update pre-existing log channels */
+ for (
+ struct log_channel * _Atomic *pprev = &global_logs, *ol;
+ ol = atomic_load_explicit(pprev, memory_order_acquire);
+ pprev = &ol->next)
+ {
+ ol->new_mask = 0;
+ if (ol->rf)
+ {
+ WALK_LIST(l, *logs)
+ if (l->rf && rf_same(l->rf, ol->rf))
+ {
+ /* Merge the mask */
+ ol->new_mask |= l->mask;
+ total_mask |= l->mask;
+
+ /* Merge flags */
+ flags |= ol->prepare;
+
+ /* The filehandle is no longer needed */
+ if ((l->rf != &rf_stderr ) && (l->rf != dbg_rf))
+ {
+ log_lock();
+ rfree(l->rf);
+ log_unlock();
+ }
+
+ l->rf = NULL;
++ l->found_old = 1;
++ }
++ }
++ else if (ol->udp_port)
++ {
++ WALK_LIST(l, *logs)
++ if (
++ (l->udp_port == ol->udp_port) && (
++ (l->udp_host && !strcmp(l->udp_host, ol->udp_host)) ||
++ (ipa_nonzero(l->udp_ip) && (ipa_equal(l->udp_ip, ol->udp_ip)))
++ ))
++ {
++ /* Merge the mask */
++ ol->new_mask |= l->mask;
++ total_mask |= l->mask;
++
++ /* Merge flags */
++ flags |= ol->prepare;
++
++ /* The socket just stays open */
++ l->found_old = 1;
+ }
+ }
+ else
++ {
+ WALK_LIST(l, *logs)
- if (!l->filename && !l->rf)
++ if (!l->filename && !l->rf && !l->udp_port)
+ {
+ ol->new_mask |= l->mask;
+ total_mask |= l->mask;
++ l->found_old = 1;
+ }
++ }
- if (current_syslog_name)
+ /* First only extend masks */
+ atomic_fetch_or_explicit(&ol->mask, ol->new_mask, memory_order_acq_rel);
+ }
+
+ atomic_fetch_or_explicit(&logging_mask, total_mask, memory_order_acq_rel);
+
+ /* Open new log channels */
+ WALK_LIST(l, *logs)
{
- if (!l->rf)
- closelog();
- xfree(current_syslog_name);
- current_syslog_name = NULL;
++ if (l->found_old)
++ continue;
++
++ if (!l->rf && !l->udp_port)
+ continue;
+
+ /* Truly new log channel */
+ log_lock();
+ struct log_channel *lc = mb_alloc(log_pool, sizeof *lc);
+ log_unlock();
+
- *lc = (struct log_channel) {
- .filename = l->filename,
- .backup = l->backup,
- .rf = l->rf,
- .limit = l->limit,
- .new_mask = l->mask,
- .prepare = BIT32_ALL(LBP_TIMESTAMP, LBP_THREAD_ID, LBP_CLASS, LBP_MSG) |
- (l->terminal_flag ? BIT32_VAL(LBPP_TERMINAL) : 0),
- };
++ if (l->rf)
++ {
++ *lc = (struct log_channel) {
++ .filename = l->filename,
++ .backup = l->backup,
++ .rf = l->rf,
++ .limit = l->limit,
++ .new_mask = l->mask,
++ .prepare = BIT32_ALL(LBP_TIMESTAMP, LBP_THREAD_ID, LBP_CLASS, LBP_MSG) |
++ (l->terminal_flag ? BIT32_VAL(LBPP_TERMINAL) : 0),
++ };
+
- /* Mask union */
- total_mask |= l->mask;
++ /* Now the file handle ownership is transferred to the log channel */
++ l->rf = NULL;
+
- /* Message preparation flags */
- flags |= lc->prepare;
++ /* Find more */
++ for (struct log_config *ll = NODE_NEXT(l); NODE_VALID(ll); ll = NODE_NEXT(ll))
++ if (ll->filename && ll->rf && rf_same(lc->rf, ll->rf))
++ {
++ /* Merged with this channel */
++ lc->new_mask |= ll->mask;
++ total_mask |= ll->mask;
++
++ if (l->rf != &rf_stderr)
++ {
++ log_lock();
++ rfree(ll->rf);
++ log_unlock();
++ }
++ ll->rf = NULL;
++ }
++ }
++ else if (l->udp_port)
++ {
++ sock *sk;
++
++ ASSERT(l->udp_host || ipa_nonzero(l->udp_ip));
+
- /* Now the file handle ownership is transferred to the log channel */
- l->rf = NULL;
++ *lc = (struct log_channel) {
++ .new_mask = l->mask,
++ .prepare = BIT32_ALL(LBP_UDP_HEADER, LBP_MSG),
++ .udp_host = l->udp_host,
++ .udp_port = l->udp_port,
++ .udp_ip = l->udp_ip,
++ };
+
- /* Find more */
- for (struct log_config *ll = NODE_NEXT(l); NODE_VALID(ll); ll = NODE_NEXT(ll))
- if (ll->filename && ll->rf && rf_same(lc->rf, ll->rf))
++ if (lc->udp_host && ipa_zero(lc->udp_ip))
+ {
- /* Merged with this channel */
- lc->new_mask |= ll->mask;
- total_mask |= ll->mask;
++ const char *err_msg;
++ lc->udp_ip = resolve_hostname(lc->udp_host, SK_UDP, &err_msg);
+
- if (l->rf != &rf_stderr)
++ if (ipa_zero(lc->udp_ip))
+ {
- log_lock();
- rfree(ll->rf);
- log_unlock();
++ cf_warn("Cannot resolve hostname '%s': %s", l->udp_host, err_msg);
++ goto resolve_fail;
+ }
- ll->rf = NULL;
+ }
+
++ log_lock();
++ sk = sk_new(log_pool);
++ log_unlock();
++ sk->type = SK_UDP;
++ sk->daddr = lc->udp_ip;
++ sk->dport = lc->udp_port;
++ sk->flags = SKF_CONNECT;
++
++ if (sk_open(sk, &main_birdloop) < 0)
++ {
++ cf_warn("Cannot open UDP log socket: %s%#m", sk->err);
++ rfree(sk);
++resolve_fail:
++ log_lock();
++ mb_free(lc);
++ log_unlock();
++ continue;
++ }
++
++ atomic_store_explicit(&lc->udp_sk, sk, memory_order_relaxed);
++
++ /* Find more */
++ for (struct log_config *ll = NODE_NEXT(l); NODE_VALID(ll); ll = NODE_NEXT(ll))
++ if (
++ (l->udp_port == ll->udp_port) && (
++ (l->udp_host && !strcmp(l->udp_host, ll->udp_host)) ||
++ (ipa_nonzero(l->udp_ip) && (ipa_equal(l->udp_ip, ll->udp_ip)))
++ ))
++ {
++ /* Merged with this channel */
++ lc->new_mask |= ll->mask;
++ total_mask |= ll->mask;
++
++ ll->found_old = 1;
++ }
++ }
++
++ /* Mask union */
++ total_mask |= l->mask;
++
++ /* Store the new final local mask */
+ atomic_store_explicit(&lc->mask, lc->new_mask, memory_order_release);
+
++ /* Message preparation flags */
++ flags |= lc->prepare;
++
+ /* Insert into the main log list */
+ struct log_channel *head = atomic_load_explicit(&global_logs, memory_order_acquire);
+ do atomic_store_explicit(&lc->next, head, memory_order_release);
+ while (!atomic_compare_exchange_strong_explicit(
+ &global_logs, &head, lc,
+ memory_order_acq_rel, memory_order_acquire));
}
- if (new_syslog_name)
+ /* Merge overall flags */
+ atomic_fetch_or_explicit(&logging_flags, flags, memory_order_acq_rel);
+ atomic_fetch_or_explicit(&logging_mask, total_mask, memory_order_acq_rel);
+
+ /* Close end-of-life log channels */
+ for (struct log_channel * _Atomic *pprev = &global_logs,
+ *ol = atomic_load_explicit(pprev, memory_order_acquire);
+ ol; )
{
- current_syslog_name = xstrdup(new_syslog_name);
- openlog(current_syslog_name, LOG_CONS | LOG_NDELAY, LOG_DAEMON);
+ /* Store new mask after opening new files to minimize missing log message race conditions */
+ atomic_store_explicit(&ol->mask, ol->new_mask, memory_order_release);
+
+ /* Never close syslog channel or debug */
- if (ol->new_mask || !ol->rf || (ol->rf == dbg_rf))
++ if (ol->new_mask || (!ol->rf && !ol->udp_sk) || (ol->rf == dbg_rf))
+ {
+ pprev = &ol->next;
+ ol = atomic_load_explicit(pprev, memory_order_acquire);
+ }
+ else
+ {
+ /* This file has no logging set up, remove from list */
+ struct log_channel *next = atomic_load_explicit(&ol->next, memory_order_acquire);
+ atomic_store_explicit(pprev, next, memory_order_release);
+
+ /* Free the channel after all worker threads leave the critical section */
+ log_lock();
+ lts_request(ol, NULL, "Log Reconfigure Close Old File");
+ log_unlock();
+
+ /* Continue to next */
+ ol = next;
+ }
}
-#endif
+ /* Set overall flags after files are closed */
+ atomic_store_explicit(&logging_flags, flags, memory_order_release);
+ atomic_store_explicit(&logging_mask, total_mask, memory_order_release);
-done:
- /* Logs exchange done, let the threads log as before */
- log_unlock();
+#ifdef HAVE_SYSLOG_H
+ if ((!current_syslog_name != !new_syslog_name)
+ || bstrcmp(current_syslog_name, new_syslog_name))
+ {
+ char *old_syslog_name = current_syslog_name;
+
+ if (new_syslog_name)
+ {
+ current_syslog_name = xstrdup(new_syslog_name);
+ openlog(current_syslog_name, LOG_CONS | LOG_NDELAY, LOG_DAEMON);
+ }
+ else
+ {
+ current_syslog_name = NULL;
+ closelog();
+ }
+
+ if (old_syslog_name)
+ xfree(old_syslog_name);
+ }
+#endif
}
void