static void
_push_tail(LogQueue *s, LogMessage *msg, const LogPathOptions *path_options)
{
LogQueueDisk *self = (LogQueueDisk *) s;
LogPathOptions local_options = *path_options;
g_static_mutex_lock(&self->super.lock);
if (self->push_tail)
{
if (self->push_tail(self, msg, &local_options, path_options))
{
log_queue_push_notify (&self->super);
stats_counter_inc(self->super.stored_messages);
log_msg_ack(msg, &local_options, AT_PROCESSED);
log_msg_unref(msg);
g_static_mutex_unlock(&self->super.lock);
return;
}
}
stats_counter_inc (self->super.dropped_messages);
if (path_options->flow_control_requested)
log_msg_ack(msg, path_options, AT_SUSPENDED);
else
log_msg_drop(msg, path_options, AT_PROCESSED);
g_static_mutex_unlock(&self->super.lock);
}
static void
log_writer_queue(LogPipe *s, LogMessage *lm, const LogPathOptions *path_options)
{
LogWriter *self = (LogWriter *) s;
if (self->options->suppress > 0 && log_writer_last_msg_check(self, lm, path_options))
return;
stats_counter_inc(self->processed_messages);
if (!log_queue_push_tail(self->queue, lm, path_options))
{
/* drop incoming message, we must ack here, otherwise the sender might
* block forever, however this should not happen unless the sum of
* window_sizes of sources feeding this writer exceeds log_fifo_size
* or if flow control is not turned on.
*/
/* we don't send a message here since the system is draining anyway */
stats_counter_inc(self->dropped_messages);
msg_debug("Destination queue full, dropping message",
evt_tag_int("queue_len", log_queue_get_length(self->queue)),
evt_tag_int("mem_fifo_size", self->options->mem_fifo_size),
NULL);
log_msg_drop(lm, path_options);
return;
}
}
void
log_dest_driver_queue_method(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options, gpointer user_data)
{
LogDestDriver *self = (LogDestDriver *) s;
stats_counter_inc(self->super.processed_group_messages);
stats_counter_inc(self->queued_global_messages);
log_pipe_forward_msg(s, msg, path_options);
}
static gboolean
afamqp_worker_insert(LogThrDestDriver *s)
{
AMQPDestDriver *self = (AMQPDestDriver *)s;
gboolean success;
LogMessage *msg;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
afamqp_dd_connect(self, TRUE);
success = log_queue_pop_head(s->queue, &msg, &path_options, FALSE, FALSE);
if (!success)
return TRUE;
msg_set_context(msg);
success = afamqp_worker_publish (self, msg);
msg_set_context(NULL);
if (success)
{
stats_counter_inc(s->stored_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
else
log_queue_push_head(s->queue, msg, &path_options);
return success;
}
void
log_src_driver_queue_method(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options, gpointer user_data)
{
LogSrcDriver *self = (LogSrcDriver *) s;
GlobalConfig *cfg = log_pipe_get_config(s);
/* $SOURCE */
if (msg->flags & LF_LOCAL)
afinter_postpone_mark(cfg->mark_freq);
log_msg_set_value(msg, LM_V_SOURCE, self->super.group, self->group_len);
stats_counter_inc(self->super.processed_group_messages);
stats_counter_inc(self->received_global_messages);
log_pipe_forward_msg(s, msg, path_options);
}
void
log_threaded_dest_driver_message_drop(LogThrDestDriver *self,
LogMessage *msg)
{
stats_counter_inc(self->dropped_messages);
log_threaded_dest_driver_message_accept(self, msg);
}
static void
log_queue_fifo_rewind_backlog(LogQueue *s, guint rewind_count)
{
LogQueueFifo *self = (LogQueueFifo *) s;
guint pos;
if (rewind_count > self->qbacklog_len)
rewind_count = self->qbacklog_len;
for (pos = 0; pos < rewind_count; pos++)
{
LogMessageQueueNode *node = iv_list_entry(self->qbacklog.prev, LogMessageQueueNode, list);
/*
* Because the message go to the backlog only in case of pop_head
* and pop_head add ack and ref when it pushes the message into the backlog
* The rewind must decrease the ack and ref too
*/
iv_list_del_init(&node->list);
iv_list_add(&node->list, &self->qoverflow_output);
self->qbacklog_len--;
self->qoverflow_output_len++;
stats_counter_inc(self->super.stored_messages);
}
}
void
log_tags_inc_counter(LogTagId id)
{
g_static_mutex_lock(&log_tags_lock);
if (id < log_tags_num)
stats_counter_inc(log_tags_list[id].counter);
g_static_mutex_unlock(&log_tags_lock);
}
/* move items from the per-thread input queue to the lock-protected "wait" queue */
static void
log_queue_fifo_move_input_unlocked(LogQueueFifo *self, gint thread_id)
{
gint queue_len;
/* since we're in the input thread, queue_len will be racy. It can
* increase due to log_queue_fifo_push_head() and can also decrease as
* items are removed from the output queue using log_queue_pop_head().
*
* The only reason we're using it here is to check for qoverflow
* overflows, however the only side-effect of the race (if lost) is that
* we would lose a couple of message too many or add some more messages to
* qoverflow than permitted by the user. Since if flow-control is used,
* the fifo size should be sized larger than the potential window sizes,
* otherwise we can lose messages anyway, this is not deemed a cost to
* justify proper locking in this case.
*/
queue_len = log_queue_fifo_get_length(&self->super);
if (queue_len + self->qoverflow_input[thread_id].len > self->qoverflow_size)
{
/* slow path, the input thread's queue would overflow the queue, let's drop some messages */
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
gint i;
gint n;
/* NOTE: MAX is needed here to ensure that the lost race on queue_len
* doesn't result in n < 0 */
n = self->qoverflow_input[thread_id].len - MAX(0, (self->qoverflow_size - queue_len));
for (i = 0; i < n; i++)
{
LogMessageQueueNode *node = iv_list_entry(self->qoverflow_input[thread_id].items.next, LogMessageQueueNode, list);
LogMessage *msg = node->msg;
iv_list_del(&node->list);
self->qoverflow_input[thread_id].len--;
path_options.ack_needed = node->ack_needed;
stats_counter_inc(self->super.dropped_messages);
log_msg_free_queue_node(node);
log_msg_drop(msg, &path_options);
}
msg_debug("Destination queue full, dropping messages",
evt_tag_int("queue_len", queue_len),
evt_tag_int("log_fifo_size", self->qoverflow_size),
evt_tag_int("count", n),
evt_tag_str("persist_name", self->super.persist_name),
NULL);
}
stats_counter_add(self->super.stored_messages, self->qoverflow_input[thread_id].len);
iv_list_splice_tail_init(&self->qoverflow_input[thread_id].items, &self->qoverflow_wait);
self->qoverflow_wait_len += self->qoverflow_input[thread_id].len;
self->qoverflow_input[thread_id].len = 0;
}
static void
_push_head (LogQueueDisk *s, LogMessage *msg, const LogPathOptions *path_options)
{
LogQueueDiskNonReliable *self = (LogQueueDiskNonReliable *) s;
g_static_mutex_lock(&self->super.super.lock);
g_queue_push_head (self->qout, LOG_PATH_OPTIONS_TO_POINTER (path_options));
g_queue_push_head (self->qout, msg);
stats_counter_inc (self->super.super.stored_messages);
g_static_mutex_unlock(&self->super.super.lock);
}
static gboolean
afmongodb_worker_insert (MongoDBDestDriver *self)
{
gboolean success;
guint8 *oid;
LogMessage *msg;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
afmongodb_dd_connect(self, TRUE);
success = log_queue_pop_head(self->queue, &msg, &path_options, FALSE, FALSE);
if (!success)
return TRUE;
msg_set_context(msg);
bson_reset (self->bson);
oid = mongo_util_oid_new_with_time (self->last_msg_stamp, self->seq_num);
bson_append_oid (self->bson, "_id", oid);
g_free (oid);
value_pairs_walk(self->vp,
afmongodb_vp_obj_start,
afmongodb_vp_process_value,
afmongodb_vp_obj_end,
msg, self->seq_num, self->bson);
bson_finish (self->bson);
if (!mongo_sync_cmd_insert_n(self->conn, self->ns, 1,
(const bson **)&self->bson))
{
msg_error("Network error while inserting into MongoDB",
evt_tag_int("time_reopen", self->time_reopen),
NULL);
success = FALSE;
}
msg_set_context(NULL);
if (success)
{
stats_counter_inc(self->stored_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
else
{
log_queue_push_head(self->queue, msg, &path_options);
}
return success;
}
/**
* log_writer_is_msg_suppressed:
*
* This function is called to suppress duplicate messages from a given host.
*
* Locking notes:
*
* There's a strict ordering requirement between suppress_lock and
* interacting with the main loop (which ml_batched_timer beind
* suppress_timer is doing).
*
* The reason is that the main thread (running
* the main loop) sometimes acquires suppress_lock (at suppress timer
* expiration) and while blocking on suppress_lock it cannot service
* main_loop_calls()
*
* This function makes it sure that ml_batched_timer_update/cancel calls are
* only done with the suppress lock released.
*
* If we do this, we might have a few unfortunate side effects due to races
* that we also try to handle:
*
* Two messages race, one of these matches the recorded last message,
* the other doesn't. In this case, moving the update on the suppress_timer
* outside of the lock region might cause two different races:
*
* 1) matching message comes first, then non-matching
*
* This case the suppress_lock protected region decides that the suppress
* timer needs to fire (#1) and then the other decides that it needs to
* be cancelled. (#2)
*
* If these are processed in order, then we are the same as if the two was
* also protected by the mutex (which is ok)
*
* If they are reversed, e.g. we first cancels the timer and the second arms it,
* then we might have a timer wakeup which will find no suppressed messages
* to report (as the non-matching message will set last_msg_count to zero). This
* spurious wakeup should be handled by the expiration callback.
*
* 1) non-matching message comes first, then matching
*
* This is simply a message reordering case, e.g. we don't
* want any suppressions to be emitted.
*
* In this case the locked regions finds that neither messages matched
* the recorded one, thus both times they decide to cancel the timer, which
* is ok. Timer cancellation can be reordered as they will have the same
* effect anyway.
*
* Returns TRUE to indicate that the message is to be suppressed.
**/
static gboolean
log_writer_is_msg_suppressed(LogWriter *self, LogMessage *lm)
{
gboolean need_to_arm_suppress_timer;
gboolean need_to_cancel_suppress_timer = FALSE;
if (self->options->suppress <= 0)
return FALSE;
g_static_mutex_lock(&self->suppress_lock);
if (self->last_msg)
{
if (_is_time_within_the_suppress_timeout(self, lm) &&
_is_message_a_repetition(lm, self->last_msg) &&
!_is_message_a_mark(lm))
{
stats_counter_inc(self->suppressed_messages);
self->last_msg_count++;
/* we only create the timer if this is the first suppressed message, otherwise it is already running. */
need_to_arm_suppress_timer = self->last_msg_count == 1;
g_static_mutex_unlock(&self->suppress_lock);
/* this has to be outside of suppress_lock */
if (need_to_arm_suppress_timer)
log_writer_arm_suppress_timer(self);
msg_debug("Suppressing duplicate message",
evt_tag_str("host", log_msg_get_value(lm, LM_V_HOST, NULL)),
evt_tag_str("msg", log_msg_get_value(lm, LM_V_MESSAGE, NULL)));
return TRUE;
}
else
{
if (self->last_msg_count)
log_writer_emit_suppress_summary(self);
else
log_writer_release_last_message(self);
need_to_cancel_suppress_timer = TRUE;
}
}
log_writer_record_last_message(self, lm);
g_static_mutex_unlock(&self->suppress_lock);
if (need_to_cancel_suppress_timer)
ml_batched_timer_cancel(&self->suppress_timer);
return FALSE;
}
/*
* stats_instant_inc_dynamic_counter
* @timestamp: if non-negative, an associated timestamp will be created and set
*
* Instantly create (if not exists) and increment a dynamic counter.
*/
void
stats_register_and_increment_dynamic_counter(gint stats_level, gint component, const gchar *id, const gchar *instance, time_t timestamp)
{
StatsCounterItem *counter, *stamp;
StatsCluster *handle;
g_assert(stats_locked);
handle = stats_register_dynamic_counter(stats_level, component, id, instance, SC_TYPE_PROCESSED, &counter);
stats_counter_inc(counter);
if (timestamp >= 0)
{
stats_register_associated_counter(handle, SC_TYPE_STAMP, &stamp);
stats_counter_set(stamp, timestamp);
stats_unregister_dynamic_counter(handle, SC_TYPE_STAMP, &stamp);
}
stats_unregister_dynamic_counter(handle, SC_TYPE_PROCESSED, &counter);
}
/*
* Put an item back to the front of the queue.
*
* This is assumed to be called only from the output thread.
*
* NOTE: It consumes the reference passed by the caller.
*/
static void
log_queue_fifo_push_head(LogQueue *s, LogMessage *msg, const LogPathOptions *path_options)
{
LogQueueFifo *self = (LogQueueFifo *) s;
LogMessageQueueNode *node;
/* we don't check limits when putting items "in-front", as it
* normally happens when we start processing an item, but at the end
* can't deliver it. No checks, no drops either. */
node = log_msg_alloc_dynamic_queue_node(msg, path_options);
iv_list_add(&node->list, &self->qoverflow_output);
self->qoverflow_output_len++;
log_msg_unref(msg);
stats_counter_inc(self->super.stored_messages);
}
/**
* log_writer_is_msg_suppressed:
*
* This function is called to suppress duplicate messages from a given host.
*
* Returns TRUE to indicate that the message is to be suppressed.
**/
static gboolean
log_writer_is_msg_suppressed(LogWriter *self, LogMessage *lm)
{
if (self->options->suppress <= 0)
return FALSE;
g_static_mutex_lock(&self->suppress_lock);
if (self->last_msg)
{
if (self->last_msg->timestamps[LM_TS_RECVD].tv_sec >= lm->timestamps[LM_TS_RECVD].tv_sec - self->options->suppress &&
strcmp(log_msg_get_value(self->last_msg, LM_V_MESSAGE, NULL), log_msg_get_value(lm, LM_V_MESSAGE, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_HOST, NULL), log_msg_get_value(lm, LM_V_HOST, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_PROGRAM, NULL), log_msg_get_value(lm, LM_V_PROGRAM, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_PID, NULL), log_msg_get_value(lm, LM_V_PID, NULL)) == 0 &&
strcmp(log_msg_get_value(lm, LM_V_MESSAGE, NULL), "-- MARK --") != 0)
{
stats_counter_inc(self->suppressed_messages);
self->last_msg_count++;
if (self->last_msg_count == 1)
{
/* we only create the timer if this is the first suppressed message, otherwise it is already running. */
log_writer_arm_suppress_timer(self);
}
g_static_mutex_unlock(&self->suppress_lock);
msg_debug("Suppressing duplicate message",
evt_tag_str("host", log_msg_get_value(lm, LM_V_HOST, NULL)),
evt_tag_str("msg", log_msg_get_value(lm, LM_V_MESSAGE, NULL)),
NULL);
return TRUE;
}
if (self->last_msg_count)
log_writer_emit_suppress_summary(self);
else
log_writer_release_last_message(self);
}
log_writer_record_last_message(self, lm);
g_static_mutex_unlock(&self->suppress_lock);
return FALSE;
}
static void
_rewind_backlog (LogQueueDisk *s, guint rewind_count)
{
guint i;
LogQueueDiskNonReliable *self = (LogQueueDiskNonReliable *) s;
rewind_count = MIN(rewind_count, _get_message_number_in_queue(self->qbacklog));
for (i = 0; i < rewind_count; i++)
{
gpointer ptr_opt = g_queue_pop_tail (self->qbacklog);
gpointer ptr_msg = g_queue_pop_tail (self->qbacklog);
g_queue_push_head (self->qout, ptr_opt);
g_queue_push_head (self->qout, ptr_msg);
stats_counter_inc (self->super.super.stored_messages);
}
}
static void
log_writer_last_msg_flush(LogWriter *self)
{
LogMessage *m;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
gchar hostname[256];
gchar buf[1024];
gssize len;
const gchar *p;
msg_debug("Suppress timer elapsed, emitting suppression summary",
NULL);
getlonghostname(hostname, sizeof(hostname));
m = log_msg_new_empty();
m->timestamps[LM_TS_STAMP] = m->timestamps[LM_TS_RECVD];
m->pri = self->last_msg->pri;
m->flags = LF_INTERNAL | LF_LOCAL;
p = log_msg_get_value(self->last_msg, LM_V_HOST, &len);
log_msg_set_value(m, LM_V_HOST, p, len);
p = log_msg_get_value(self->last_msg, LM_V_PROGRAM, &len);
log_msg_set_value(m, LM_V_PROGRAM, p, len);
len = g_snprintf(buf, sizeof(buf), "Last message '%.20s' repeated %d times, supressed by syslog-ng on %s",
log_msg_get_value(self->last_msg, LM_V_MESSAGE, NULL),
self->last_msg_count,
hostname);
log_msg_set_value(m, LM_V_MESSAGE, buf, len);
path_options.flow_control = FALSE;
if (!log_queue_push_tail(self->queue, m, &path_options))
{
stats_counter_inc(self->dropped_messages);
msg_debug("Destination queue full, dropping suppressed message",
evt_tag_int("queue_len", log_queue_get_length(self->queue)),
evt_tag_int("mem_fifo_size", self->options->mem_fifo_size),
NULL);
log_msg_drop(m, &path_options);
}
log_writer_last_msg_release(self);
}
/* NOTE: runs in the reader thread */
static void
log_writer_queue(LogPipe *s, LogMessage *lm, const LogPathOptions *path_options, gpointer user_data)
{
LogWriter *self = (LogWriter *) s;
LogPathOptions local_options;
if (!path_options->flow_control_requested &&
(self->suspended || !(self->flags & LW_SOFT_FLOW_CONTROL)))
{
/* NOTE: this code ACKs the message back if there's a write error in
* order not to hang the client in case of a disk full */
path_options = log_msg_break_ack(lm, path_options, &local_options);
}
if (self->options->suppress > 0 && log_writer_last_msg_check(self, lm, path_options))
return;
stats_counter_inc(self->processed_messages);
log_queue_push_tail(self->queue, lm, path_options);
}
static void
log_threaded_dest_driver_queue(LogPipe *s, LogMessage *msg,
const LogPathOptions *path_options,
gpointer user_data)
{
LogThrDestDriver *self = (LogThrDestDriver *)s;
LogPathOptions local_options;
if (!path_options->flow_control_requested)
path_options = log_msg_break_ack(msg, path_options, &local_options);
if (self->queue_method)
self->queue_method(self);
log_msg_add_ack(msg, path_options);
log_queue_push_tail(self->queue, log_msg_ref(msg), path_options);
stats_counter_inc(self->processed_messages);
log_dest_driver_queue_method(s, msg, path_options, user_data);
}
/**
* log_writer_last_msg_check:
*
* This function is called to suppress duplicate messages from a given host.
*
* Returns TRUE to indicate that the message was consumed.
**/
static gboolean
log_writer_last_msg_check(LogWriter *self, LogMessage *lm, const LogPathOptions *path_options)
{
if (self->last_msg)
{
if (self->last_msg->timestamps[LM_TS_RECVD].time.tv_sec >= lm->timestamps[LM_TS_RECVD].time.tv_sec - self->options->suppress &&
strcmp(log_msg_get_value(self->last_msg, LM_V_MESSAGE, NULL), log_msg_get_value(lm, LM_V_MESSAGE, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_HOST, NULL), log_msg_get_value(lm, LM_V_HOST, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_PROGRAM, NULL), log_msg_get_value(lm, LM_V_PROGRAM, NULL)) == 0 &&
strcmp(log_msg_get_value(self->last_msg, LM_V_PID, NULL), log_msg_get_value(lm, LM_V_PID, NULL)) == 0 &&
strcmp(log_msg_get_value(lm, LM_V_MESSAGE, NULL), "-- MARK --") != 0)
{
stats_counter_inc(self->suppressed_messages);
msg_debug("Suppressing duplicate message",
evt_tag_str("host", log_msg_get_value(lm, LM_V_HOST, NULL)),
evt_tag_str("msg", log_msg_get_value(lm, LM_V_MESSAGE, NULL)),
NULL);
self->last_msg_count++;
if (self->last_msg_count == 1)
{
/* we only create the timer if there's at least one suppressed message */
self->last_msg_timerid = g_timeout_add(self->options->suppress * 1000, last_msg_timer, self);
}
log_msg_drop(lm, path_options);
return TRUE;
}
if (self->last_msg_count)
log_writer_last_msg_flush(self);
else
log_writer_last_msg_release(self);
}
log_writer_last_msg_record(self, lm);
return FALSE;
}
/* NOTE: runs in the reader thread */
static void
log_writer_queue(LogPipe *s, LogMessage *lm, const LogPathOptions *path_options, gpointer user_data)
{
LogWriter *self = (LogWriter *) s;
LogPathOptions local_options;
gint mark_mode = self->options->mark_mode;
if (!path_options->flow_control_requested &&
(self->suspended || !(self->flags & LW_SOFT_FLOW_CONTROL)))
{
/* NOTE: this code ACKs the message back if there's a write error in
* order not to hang the client in case of a disk full */
path_options = log_msg_break_ack(lm, path_options, &local_options);
}
if (log_writer_is_msg_suppressed(self, lm))
{
log_msg_drop(lm, path_options);
return;
}
if (mark_mode != MM_INTERNAL && (lm->flags & LF_INTERNAL) && (lm->flags & LF_MARK))
{
/* drop MARK messages generated by internal() in case our mark-mode != internal */
log_msg_drop(lm, path_options);
return;
}
if (mark_mode == MM_DST_IDLE || (mark_mode == MM_HOST_IDLE && !(lm->flags & LF_LOCAL)))
{
/* in dst-idle and host-idle most, messages postpone the MARK itself */
log_writer_postpone_mark_timer(self);
}
stats_counter_inc(self->processed_messages);
log_queue_push_tail(self->queue, lm, path_options);
}
/* this is the callback function that gets called when the MARK timeout
* elapsed. It runs in the main thread.
*/
static void
log_writer_mark_timeout(void *cookie)
{
LogWriter *self = (LogWriter *)cookie;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
const gchar *hostname;
gsize hostname_len;
LogMessage *msg;
main_loop_assert_main_thread();
msg = log_msg_new_mark();
/* timeout: there was no new message on the writer or it is in periodical mode */
hostname = resolve_sockaddr_to_hostname(&hostname_len, msg->saddr, &self->options->host_resolve_options);
log_msg_set_value(msg, LM_V_HOST, hostname, hostname_len);
/* set the current time in the message stamp */
msg->timestamps[LM_TS_STAMP] = msg->timestamps[LM_TS_RECVD];
if (!log_writer_is_msg_suppressed(self, msg))
{
log_queue_push_tail(self->queue, msg, &path_options);
stats_counter_inc(self->processed_messages);
}
else
{
log_msg_drop(msg, &path_options);
}
/* we need to issue another MARK in all mark-mode cases that already
* triggered this callback (dst-idle, host-idle, periodical). The
* original setup of the timer is at a different location:
* - log_writer_queue() for "*-idle" modes
* - log_writer_init() for periodical mode
*/
log_writer_postpone_mark_timer(self);
}
static gboolean
afsql_dd_insert_fail_handler(AFSqlDestDriver *self, LogMessage *msg,
LogPathOptions *path_options)
{
if (self->failed_message_counter < self->num_retries - 1)
{
log_queue_push_head(self->queue, msg, path_options);
/* database connection status sanity check after failed query */
if (dbi_conn_ping(self->dbi_ctx) != 1)
{
const gchar *dbi_error;
dbi_conn_error(self->dbi_ctx, &dbi_error);
msg_error("Error, no SQL connection after failed query attempt",
evt_tag_str("type", self->type),
evt_tag_str("host", self->host),
evt_tag_str("port", self->port),
evt_tag_str("username", self->user),
evt_tag_str("database", self->database),
evt_tag_str("error", dbi_error),
NULL);
return FALSE;
}
self->failed_message_counter++;
return FALSE;
}
msg_error("Multiple failures while inserting this record into the database, message dropped",
evt_tag_int("attempts", self->num_retries),
NULL);
stats_counter_inc(self->dropped_messages);
log_msg_drop(msg, path_options);
self->failed_message_counter = 0;
return TRUE;
}
static gboolean
perl_worker_eval(LogThrDestDriver *d)
{
PerlDestDriver *self = (PerlDestDriver *)d;
gboolean success, vp_ok;
LogMessage *msg;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
PerlInterpreter *my_perl = self->perl;
int count;
HV *kvmap;
gpointer args[3];
dSP;
success = log_queue_pop_head(self->super.queue, &msg, &path_options, FALSE, FALSE);
if (!success)
return TRUE;
msg_set_context(msg);
ENTER;
SAVETMPS;
PUSHMARK(SP);
kvmap = newHV();
args[0] = self->perl;
args[1] = kvmap;
args[2] = self;
vp_ok = value_pairs_foreach(self->vp, perl_worker_vp_add_one,
msg, self->seq_num, LTZ_SEND,
&self->template_options,
args);
if (!vp_ok && (self->template_options.on_error & ON_ERROR_DROP_MESSAGE))
goto exit;
XPUSHs(sv_2mortal(newRV_noinc((SV *)kvmap)));
PUTBACK;
count = call_pv(self->queue_func_name, G_EVAL | G_SCALAR);
SPAGAIN;
msg_set_context(NULL);
if (SvTRUE(ERRSV))
{
msg_error("Error while calling a Perl function",
evt_tag_str("driver", self->super.super.super.id),
evt_tag_str("script", self->filename),
evt_tag_str("function", self->queue_func_name),
evt_tag_str("error-message", SvPV_nolen(ERRSV)),
NULL);
(void) POPs;
success = FALSE;
}
if (count != 1)
{
msg_error("Too many values returned by a Perl function",
evt_tag_str("driver", self->super.super.super.id),
evt_tag_str("script", self->filename),
evt_tag_str("function", self->queue_func_name),
evt_tag_int("returned-values", count),
evt_tag_int("expected-values", 1),
NULL);
success = FALSE;
}
else
{
int r = POPi;
success = (r != 0);
}
exit:
PUTBACK;
FREETMPS;
LEAVE;
if (success && vp_ok)
{
stats_counter_inc(self->super.stored_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
else
{
stats_counter_inc(self->super.dropped_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
return success;
}
static void
log_source_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options, gpointer user_data)
{
LogSource *self = (LogSource *) s;
LogPathOptions local_options = *path_options;
gint old_window_size;
gint i;
msg_set_context(msg);
if (msg->timestamps[LM_TS_STAMP].tv_sec == -1 || !self->options->keep_timestamp)
msg->timestamps[LM_TS_STAMP] = msg->timestamps[LM_TS_RECVD];
g_assert(msg->timestamps[LM_TS_STAMP].zone_offset != -1);
ack_tracker_track_msg(self->ack_tracker, msg);
/* $HOST setup */
log_source_mangle_hostname(self, msg);
/* $PROGRAM override */
if (self->options->program_override)
{
if (self->options->program_override_len < 0)
self->options->program_override_len = strlen(self->options->program_override);
log_msg_set_value(msg, LM_V_PROGRAM, self->options->program_override, self->options->program_override_len);
}
/* $HOST override */
if (self->options->host_override)
{
if (self->options->host_override_len < 0)
self->options->host_override_len = strlen(self->options->host_override);
log_msg_set_value(msg, LM_V_HOST, self->options->host_override, self->options->host_override_len);
}
/* source specific tags */
if (self->options->tags)
{
for (i = 0; i < self->options->tags->len; i++)
{
log_msg_set_tag_by_id(msg, g_array_index(self->options->tags, LogTagId, i));
}
}
log_msg_set_tag_by_id(msg, self->options->source_group_tag);
/* stats counters */
if (stats_check_level(2))
{
stats_lock();
stats_register_and_increment_dynamic_counter(2, SCS_HOST | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_HOST, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
if (stats_check_level(3))
{
stats_register_and_increment_dynamic_counter(3, SCS_SENDER | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_HOST_FROM, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
stats_register_and_increment_dynamic_counter(3, SCS_PROGRAM | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_PROGRAM, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
}
stats_unlock();
}
stats_syslog_process_message_pri(msg->pri);
/* message setup finished, send it out */
/* NOTE: we start by enabling flow-control, thus we need an acknowledgement */
local_options.ack_needed = TRUE;
log_msg_ref(msg);
log_msg_add_ack(msg, &local_options);
msg->ack_func = log_source_msg_ack;
old_window_size = g_atomic_counter_exchange_and_add(&self->window_size, -1);
/*
* NOTE: this assertion validates that the source is not overflowing its
* own flow-control window size, decreased above, by the atomic statement.
*
* If the _old_ value is zero, that means that the decrement operation
* above has decreased the value to -1.
*/
g_assert(old_window_size > 0);
stats_counter_inc(self->recvd_messages);
stats_counter_set(self->last_message_seen, msg->timestamps[LM_TS_RECVD].tv_sec);
log_pipe_forward_msg(s, msg, &local_options);
msg_set_context(NULL);
if (accurate_nanosleep && self->threaded && self->window_full_sleep_nsec > 0 && !log_source_free_to_send(self))
{
struct timespec ts;
/* wait one 0.1msec in the hope that the buffer clears up */
ts.tv_sec = 0;
ts.tv_nsec = self->window_full_sleep_nsec;
nanosleep(&ts, NULL);
}
}
static gboolean
afmongodb_worker_insert (MongoDBDestDriver *self)
{
gboolean success;
guint8 *oid;
LogMessage *msg;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
afmongodb_dd_connect(self, TRUE);
g_mutex_lock(self->queue_mutex);
log_queue_reset_parallel_push(self->queue);
success = log_queue_pop_head(self->queue, &msg, &path_options, FALSE, FALSE);
g_mutex_unlock(self->queue_mutex);
if (!success)
return TRUE;
msg_set_context(msg);
bson_reset (self->bson_sel);
bson_reset (self->bson_upd);
bson_reset (self->bson_set);
oid = mongo_util_oid_new_with_time (self->last_msg_stamp, self->seq_num);
bson_append_oid (self->bson_sel, "_id", oid);
g_free (oid);
bson_finish (self->bson_sel);
value_pairs_foreach (self->vp, afmongodb_vp_foreach,
msg, self->seq_num, self->bson_set);
bson_finish (self->bson_set);
bson_append_document (self->bson_upd, "$set", self->bson_set);
bson_finish (self->bson_upd);
if (!mongo_sync_cmd_update (self->conn, self->ns, MONGO_WIRE_FLAG_UPDATE_UPSERT,
self->bson_sel, self->bson_upd))
{
msg_error ("Network error while inserting into MongoDB",
evt_tag_int("time_reopen", self->time_reopen),
NULL);
success = FALSE;
}
msg_set_context(NULL);
if (success)
{
stats_counter_inc(self->stored_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
else
{
g_mutex_lock(self->queue_mutex);
log_queue_push_head(self->queue, msg, &path_options);
g_mutex_unlock(self->queue_mutex);
}
return success;
}
/**
* Assumed to be called from one of the input threads. If the thread_id
* cannot be determined, the item is put directly in the wait queue.
*
* Puts the message to the queue, and logs an error if it caused the
* queue to be full.
*
* It attempts to put the item to the per-thread input queue.
*
* NOTE: It consumes the reference passed by the caller.
**/
static void
log_queue_fifo_push_tail(LogQueue *s, LogMessage *msg, const LogPathOptions *path_options)
{
LogQueueFifo *self = (LogQueueFifo *) s;
gint thread_id;
LogMessageQueueNode *node;
thread_id = main_loop_io_worker_thread_id();
g_assert(thread_id < 0 || log_queue_max_threads > thread_id);
/* NOTE: we don't use high-water marks for now, as log_fetch_limit
* limits the number of items placed on the per-thread input queue
* anyway, and any sane number decreased the performance measurably.
*
* This means that per-thread input queues contain _all_ items that
* a single poll iteration produces. And once the reader is finished
* (either because the input is depleted or because of
* log_fetch_limit / window_size) the whole bunch is propagated to
* the "wait" queue.
*/
if (thread_id >= 0) {
/* fastpath, use per-thread input FIFOs */
if (!self->qoverflow_input[thread_id].finish_cb_registered)
{
/* this is the first item in the input FIFO, register a finish
* callback to make sure it gets moved to the wait_queue if the
* input thread finishes */
main_loop_io_worker_register_finish_callback(&self->qoverflow_input[thread_id].cb);
self->qoverflow_input[thread_id].finish_cb_registered = TRUE;
}
node = log_msg_alloc_queue_node(msg, path_options);
iv_list_add_tail(&node->list, &self->qoverflow_input[thread_id].items);
self->qoverflow_input[thread_id].len++;
log_msg_unref(msg);
return;
}
/* slow path, put the pending item and the whole input queue to the wait_queue */
g_static_mutex_lock(&self->super.lock);
if (thread_id >= 0)
log_queue_fifo_move_input_unlocked(self, thread_id);
if (log_queue_fifo_get_length(s) < self->qoverflow_size)
{
node = log_msg_alloc_queue_node(msg, path_options);
iv_list_add_tail(&node->list, &self->qoverflow_wait);
self->qoverflow_wait_len++;
log_queue_push_notify(&self->super);
stats_counter_inc(self->super.stored_messages);
g_static_mutex_unlock(&self->super.lock);
log_msg_unref(msg);
}
else
{
stats_counter_inc(self->super.dropped_messages);
g_static_mutex_unlock(&self->super.lock);
log_msg_drop(msg, path_options);
msg_debug("Destination queue full, dropping message",
evt_tag_int("queue_len", log_queue_fifo_get_length(&self->super)),
evt_tag_int("log_fifo_size", self->qoverflow_size),
NULL);
}
return;
}
/**
* afsql_dd_insert_db:
*
* This function is running in the database thread
*
* Returns: FALSE to indicate that the connection should be closed and
* this destination suspended for time_reopen() time.
**/
static gboolean
afsql_dd_insert_db(AFSqlDestDriver *self)
{
GString *table = NULL;
GString *insert_command = NULL;
LogMessage *msg;
gboolean success;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
if (!afsql_dd_ensure_initialized_connection(self))
return FALSE;
/* connection established, try to insert a message */
success = log_queue_pop_head(self->queue, &msg, &path_options, FALSE, self->flags & AFSQL_DDF_EXPLICIT_COMMITS);
if (!success)
return TRUE;
msg_set_context(msg);
table = afsql_dd_ensure_accessible_database_table(self, msg);
if (!table)
{
success = FALSE;
goto out;
}
if (afsql_dd_should_start_new_transaction(self) && !afsql_dd_begin_txn(self))
{
success = FALSE;
goto out;
}
insert_command = afsql_dd_build_insert_command(self, msg, table);
success = afsql_dd_run_query(self, insert_command->str, FALSE, NULL);
if (success && self->flush_lines_queued != -1)
{
self->flush_lines_queued++;
if (afsql_dd_should_commit_transaction(self) && !afsql_dd_commit_txn(self))
{
/* Assuming that in case of error, the queue is rewound by afsql_dd_commit_txn() */
g_string_free(insert_command, TRUE);
msg_set_context(NULL);
return FALSE;
}
}
out:
if (table != NULL)
g_string_free(table, TRUE);
if (insert_command != NULL)
g_string_free(insert_command, TRUE);
msg_set_context(NULL);
if (success)
{
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
step_sequence_number(&self->seq_num);
self->failed_message_counter = 0;
}
else
{
if (self->failed_message_counter < self->num_retries - 1)
{
if (!afsql_dd_handle_insert_row_error_depending_on_connection_availability(self, msg, &path_options))
return FALSE;
self->failed_message_counter++;
}
else
{
msg_error("Multiple failures while inserting this record into the database, message dropped",
evt_tag_int("attempts", self->num_retries),
NULL);
stats_counter_inc(self->dropped_messages);
log_msg_drop(msg, &path_options);
self->failed_message_counter = 0;
success = TRUE;
}
}
return success;
}
static gboolean
redis_worker_insert(LogThrDestDriver *s)
{
RedisDriver *self = (RedisDriver *)s;
gboolean success;
LogMessage *msg;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
redisReply *reply;
const char *argv[5];
size_t argvlen[5];
int argc = 2;
redis_dd_connect(self, TRUE);
if (self->c->err)
return FALSE;
success = log_queue_pop_head(self->super.queue, &msg, &path_options, FALSE, FALSE);
if (!success)
return TRUE;
msg_set_context(msg);
log_template_format(self->key, msg, &self->template_options, LTZ_SEND,
self->seq_num, NULL, self->key_str);
if (self->param1)
log_template_format(self->param1, msg, &self->template_options, LTZ_SEND,
self->seq_num, NULL, self->param1_str);
if (self->param2)
log_template_format(self->param2, msg, &self->template_options, LTZ_SEND,
self->seq_num, NULL, self->param2_str);
argv[0] = self->command->str;
argvlen[0] = self->command->len;
argv[1] = self->key_str->str;
argvlen[1] = self->key_str->len;
if (self->param1)
{
argv[2] = self->param1_str->str;
argvlen[2] = self->param1_str->len;
argc++;
}
if (self->param2)
{
argv[3] = self->param2_str->str;
argvlen[3] = self->param2_str->len;
argc++;
}
reply = redisCommandArgv(self->c, argc, argv, argvlen);
msg_debug("REDIS command sent",
evt_tag_str("driver", self->super.super.super.id),
evt_tag_str("command", self->command->str),
evt_tag_str("key", self->key_str->str),
evt_tag_str("param1", self->param1_str->str),
evt_tag_str("param2", self->param2_str->str),
NULL);
success = TRUE;
freeReplyObject(reply);
msg_set_context(NULL);
if (success)
{
stats_counter_inc(self->super.stored_messages);
step_sequence_number(&self->seq_num);
log_msg_ack(msg, &path_options);
log_msg_unref(msg);
}
else
{
log_queue_push_head(self->super.queue, msg, &path_options);
}
return success;
}
static void
log_source_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options, gpointer user_data)
{
LogSource *self = (LogSource *) s;
gint i;
msg_set_context(msg);
if (msg->timestamps[LM_TS_STAMP].tv_sec == -1 || !self->options->keep_timestamp)
msg->timestamps[LM_TS_STAMP] = msg->timestamps[LM_TS_RECVD];
g_assert(msg->timestamps[LM_TS_STAMP].zone_offset != -1);
/* $HOST setup */
log_source_mangle_hostname(self, msg);
/* $PROGRAM override */
if (self->options->program_override)
{
if (self->options->program_override_len < 0)
self->options->program_override_len = strlen(self->options->program_override);
log_msg_set_value(msg, LM_V_PROGRAM, self->options->program_override, self->options->program_override_len);
}
/* $HOST override */
if (self->options->host_override)
{
if (self->options->host_override_len < 0)
self->options->host_override_len = strlen(self->options->host_override);
log_msg_set_value(msg, LM_V_HOST, self->options->host_override, self->options->host_override_len);
}
/* source specific tags */
if (self->options->tags)
{
for (i = 0; i < self->options->tags->len; i++)
{
log_msg_set_tag_by_id(msg, g_array_index(self->options->tags, LogTagId, i));
}
}
log_msg_set_tag_by_id(msg, self->options->source_group_tag);
/* stats counters */
if (stats_check_level(2))
{
stats_lock();
stats_register_and_increment_dynamic_counter(2, SCS_HOST | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_HOST, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
if (stats_check_level(3))
{
stats_register_and_increment_dynamic_counter(3, SCS_SENDER | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_HOST_FROM, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
stats_register_and_increment_dynamic_counter(3, SCS_PROGRAM | SCS_SOURCE, NULL, log_msg_get_value(msg, LM_V_PROGRAM, NULL), msg->timestamps[LM_TS_RECVD].tv_sec);
}
stats_unlock();
}
stats_syslog_process_message_pri(msg->pri);
/* message setup finished, send it out */
stats_counter_inc(self->recvd_messages);
stats_counter_set(self->last_message_seen, msg->timestamps[LM_TS_RECVD].tv_sec);
log_pipe_forward_msg(s, msg, path_options);
msg_set_context(NULL);
if (accurate_nanosleep && self->threaded && self->window_full_sleep_nsec > 0 && !log_source_free_to_send(self))
{
struct timespec ts;
/* wait one 0.1msec in the hope that the buffer clears up */
ts.tv_sec = 0;
ts.tv_nsec = self->window_full_sleep_nsec;
nanosleep(&ts, NULL);
}
}
