void
log_queue_set_counters(LogQueue *self, StatsCounterItem *stored_messages, StatsCounterItem *dropped_messages)
{
self->stored_messages = stored_messages;
self->dropped_messages = dropped_messages;
stats_counter_set(self->stored_messages, log_queue_get_length(self));
}
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;
}
}
static void
afmongodb_dd_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options, gpointer user_data)
{
MongoDBDestDriver *self = (MongoDBDestDriver *)s;
gboolean queue_was_empty;
LogPathOptions local_options;
if (!path_options->flow_control_requested)
path_options = log_msg_break_ack(msg, path_options, &local_options);
g_mutex_lock(self->queue_mutex);
self->last_msg_stamp = cached_g_current_time_sec ();
queue_was_empty = log_queue_get_length(self->queue) == 0;
g_mutex_unlock(self->queue_mutex);
log_msg_add_ack(msg, path_options);
log_queue_push_tail(self->queue, log_msg_ref(msg), path_options);
g_mutex_lock(self->suspend_mutex);
if (queue_was_empty && !self->writer_thread_suspended)
{
g_mutex_lock(self->queue_mutex);
log_queue_set_parallel_push(self->queue, 1, afmongodb_dd_queue_notify, self, NULL);
g_mutex_unlock(self->queue_mutex);
}
g_mutex_unlock(self->suspend_mutex);
log_dest_driver_queue_method(s, msg, path_options, user_data);
}
static gboolean
log_writer_fd_check(GSource *source)
{
LogWriterWatch *self = (LogWriterWatch *) source;
gint64 num_elements = log_queue_get_length(self->writer->queue);
if (self->error_suspend)
return FALSE;
if (num_elements && !log_writer_throttling(self->writer))
{
/* we have data to flush */
if (self->flush_waiting_for_timeout)
{
GTimeVal tv;
/* check if timeout elapsed */
g_source_get_current_time(source, &tv);
if (!(self->flush_target.tv_sec <= tv.tv_sec || (self->flush_target.tv_sec == tv.tv_sec && self->flush_target.tv_usec <= tv.tv_usec)))
return FALSE;
if ((self->writer->flags & LW_ALWAYS_WRITABLE))
return TRUE;
}
}
return !!(self->pollfd.revents & (G_IO_OUT | G_IO_ERR | G_IO_HUP | G_IO_IN));
}
/* runs in a dedicated thread */
static LogThreadedFetchResult
_fetch(LogThreadedFetcherDriver *s)
{
ThreadedDiskqSourceDriver *self = (ThreadedDiskqSourceDriver *) s;
LogPathOptions local_options = LOG_PATH_OPTIONS_INIT;
gint64 remaining_messages = log_queue_get_length(self->queue);
LogMessage *msg = log_queue_pop_head(self->queue, &local_options);
if (!msg)
{
if (remaining_messages != 0)
msg_error("Closing corrupt diskq file, waiting for new", evt_tag_long("lost_messages", remaining_messages),
evt_tag_str("file", self->filename));
else
msg_info("Diskq file has been read, waiting for new file", evt_tag_str("file", self->filename));
_close_diskq(s);
self->waiting_for_file_change = TRUE;
LogThreadedFetchResult result = { THREADED_FETCH_NOT_CONNECTED, NULL };
return result;
}
LogThreadedFetchResult result = { THREADED_FETCH_SUCCESS, msg };
return result;
}
static gboolean
log_writer_fd_dispatch(GSource *source,
GSourceFunc callback,
gpointer user_data)
{
LogWriterWatch *self = (LogWriterWatch *) source;
gint64 num_elements = log_queue_get_length(self->writer->queue);
if (self->pollfd.revents & (G_IO_HUP | G_IO_IN) && self->input_means_connection_broken)
{
msg_error("EOF occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self->writer, NC_CLOSE);
return FALSE;
}
else if (self->pollfd.revents & (G_IO_ERR) && num_elements == 0)
{
msg_error("POLLERR occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self->writer, NC_WRITE_ERROR);
}
else if (num_elements)
{
if (!log_writer_flush_log(self->writer, self->proto))
{
self->error_suspend = TRUE;
g_source_get_current_time(source, &self->error_suspend_target);
g_time_val_add(&self->error_suspend_target, self->writer->options->time_reopen * 1e6);
log_writer_broken(self->writer, NC_WRITE_ERROR);
if (self->writer->source == (GSource *) self)
{
msg_notice("Suspending write operation because of an I/O error",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
evt_tag_int("time_reopen", self->writer->options->time_reopen),
NULL);
}
return TRUE;
}
}
return TRUE;
}
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);
}
/*
*
* @batch_items: the number of items processed in a batch (e.g. the number of items the consumer is preferred to process at a single invocation)
* @partial_batch: true is returned if some elements (but less than batch_items) are already buffered
* @timeout: the number of milliseconds that the consumer needs to wait before we can possibly proceed
*/
gboolean
log_queue_check_items(LogQueue *self, gint *timeout, LogQueuePushNotifyFunc parallel_push_notify, gpointer user_data,
GDestroyNotify user_data_destroy)
{
gint64 num_elements;
g_static_mutex_lock(&self->lock);
/* drop reference to the previous callback/userdata */
if (self->parallel_push_data && self->parallel_push_data_destroy)
self->parallel_push_data_destroy(self->parallel_push_data);
num_elements = log_queue_get_length(self);
if (num_elements == 0)
{
self->parallel_push_notify = parallel_push_notify;
self->parallel_push_data = user_data;
self->parallel_push_data_destroy = user_data_destroy;
g_static_mutex_unlock(&self->lock);
return FALSE;
}
/* consume the user_data reference as we won't use the callback */
if (user_data && user_data_destroy)
user_data_destroy(user_data);
self->parallel_push_notify = NULL;
self->parallel_push_data = NULL;
g_static_mutex_unlock(&self->lock);
/* recalculate buckets, throttle is only running in the output thread, no need to lock it. */
if (self->throttle > 0)
{
gint64 diff;
gint new_buckets;
GTimeVal now;
g_get_current_time(&now);
/* throttling is enabled, calculate new buckets */
if (self->last_throttle_check.tv_sec != 0)
{
diff = g_time_val_diff(&now, &self->last_throttle_check);
}
else
{
diff = 0;
self->last_throttle_check = now;
}
new_buckets = (self->throttle * diff) / G_USEC_PER_SEC;
if (new_buckets)
{
/* if new_buckets is zero, we don't save the current time as
* last_throttle_check. The reason is that new_buckets could be
* rounded to zero when only a minimal interval passes between
* poll iterations.
*/
self->throttle_buckets = MIN(self->throttle, self->throttle_buckets + new_buckets);
self->last_throttle_check = now;
}
if (num_elements && self->throttle_buckets == 0)
{
if (timeout)
{
/* we are unable to send because of throttling, make sure that we
* wake up when the rate limits lets us send at least 1 message */
*timeout = (1000 / self->throttle) + 1;
msg_debug("Throttling output",
evt_tag_int("wait", *timeout));
}
return FALSE;
}
}
return TRUE;
}
static gpointer
afmongodb_worker_thread (gpointer arg)
{
MongoDBDestDriver *self = (MongoDBDestDriver *)arg;
gboolean success;
msg_debug ("Worker thread started",
evt_tag_str("driver", self->super.super.id),
NULL);
success = afmongodb_dd_connect(self, FALSE);
self->ns = g_strconcat (self->db, ".", self->coll, NULL);
self->current_value = g_string_sized_new(256);
self->bson_sel = bson_new_sized(64);
self->bson_upd = bson_new_sized(512);
self->bson_set = bson_new_sized(512);
while (!self->writer_thread_terminate)
{
g_mutex_lock(self->suspend_mutex);
if (self->writer_thread_suspended)
{
g_cond_timed_wait(self->writer_thread_wakeup_cond,
self->suspend_mutex,
&self->writer_thread_suspend_target);
self->writer_thread_suspended = FALSE;
g_mutex_unlock(self->suspend_mutex);
}
else
{
g_mutex_unlock(self->suspend_mutex);
g_mutex_lock(self->queue_mutex);
if (log_queue_get_length(self->queue) == 0)
{
g_cond_wait(self->writer_thread_wakeup_cond, self->queue_mutex);
}
g_mutex_unlock(self->queue_mutex);
}
if (self->writer_thread_terminate)
break;
if (!afmongodb_worker_insert (self))
{
afmongodb_dd_disconnect(self);
afmongodb_dd_suspend(self);
}
}
afmongodb_dd_disconnect(self);
g_free (self->ns);
g_string_free (self->current_value, TRUE);
bson_free (self->bson_sel);
bson_free (self->bson_upd);
bson_free (self->bson_set);
msg_debug ("Worker thread finished",
evt_tag_str("driver", self->super.super.id),
NULL);
return NULL;
}
/**
* afsql_dd_database_thread:
*
* This is the thread inserting records into the database.
**/
static void
afsql_dd_database_thread(gpointer arg)
{
AFSqlDestDriver *self = (AFSqlDestDriver *) arg;
msg_verbose("Database thread started",
evt_tag_str("driver", self->super.super.id),
NULL);
while (!self->db_thread_terminate)
{
g_mutex_lock(self->db_thread_mutex);
if (self->db_thread_suspended)
{
afsql_dd_wait_for_suspension_wakeup(self);
/* we loop back to check if the thread was requested to terminate */
}
else if (!log_queue_check_items(self->queue, NULL, afsql_dd_message_became_available_in_the_queue, self, NULL))
{
/* we have nothing to INSERT into the database, let's wait we get some new stuff */
if (self->flush_lines_queued > 0)
{
if (!afsql_dd_commit_txn(self))
{
afsql_dd_disconnect(self);
afsql_dd_suspend(self);
g_mutex_unlock(self->db_thread_mutex);
continue;
}
}
else if (!self->db_thread_terminate)
{
g_cond_wait(self->db_thread_wakeup_cond, self->db_thread_mutex);
}
/* we loop back to check if the thread was requested to terminate */
}
g_mutex_unlock(self->db_thread_mutex);
if (self->db_thread_terminate)
break;
if (!afsql_dd_insert_db(self))
{
afsql_dd_disconnect(self);
afsql_dd_suspend(self);
}
}
while (log_queue_get_length(self->queue) > 0)
{
if (!afsql_dd_insert_db(self))
{
goto exit;
}
}
if (self->flush_lines_queued > 0)
{
/* we can't do anything with the return value here. if commit isn't
* successful, we get our backlog back, but we have no chance
* submitting that back to the SQL engine.
*/
afsql_dd_commit_txn(self);
}
exit:
afsql_dd_disconnect(self);
msg_verbose("Database thread finished",
evt_tag_str("driver", self->super.super.id),
NULL);
}
/**
* afsql_dd_database_thread:
*
* This is the thread inserting records into the database.
**/
static gpointer
afsql_dd_database_thread(gpointer arg)
{
AFSqlDestDriver *self = (AFSqlDestDriver *) arg;
msg_verbose("Database thread started",
evt_tag_str("driver", self->super.super.id),
NULL);
while (!self->db_thread_terminate)
{
g_mutex_lock(self->db_thread_mutex);
if (self->db_thread_suspended)
{
/* we got suspended, probably because of a connection error,
* during this time we only get wakeups if we need to be
* terminated. */
if (!self->db_thread_terminate)
g_cond_timed_wait(self->db_thread_wakeup_cond, self->db_thread_mutex, &self->db_thread_suspend_target);
self->db_thread_suspended = FALSE;
g_mutex_unlock(self->db_thread_mutex);
/* we loop back to check if the thread was requested to terminate */
}
else if (log_queue_get_length(self->queue) == 0)
{
/* we have nothing to INSERT into the database, let's wait we get some new stuff */
if (self->flush_lines_queued > 0 && self->flush_timeout > 0)
{
GTimeVal flush_target;
g_get_current_time(&flush_target);
g_time_val_add(&flush_target, self->flush_timeout * 1000);
if (!self->db_thread_terminate && !g_cond_timed_wait(self->db_thread_wakeup_cond, self->db_thread_mutex, &flush_target))
{
/* timeout elapsed */
if (!afsql_dd_commit_txn(self, FALSE))
{
afsql_dd_disconnect(self);
afsql_dd_suspend(self);
g_mutex_unlock(self->db_thread_mutex);
continue;
}
}
}
else if (!self->db_thread_terminate)
{
g_cond_wait(self->db_thread_wakeup_cond, self->db_thread_mutex);
}
g_mutex_unlock(self->db_thread_mutex);
/* we loop back to check if the thread was requested to terminate */
}
else
g_mutex_unlock(self->db_thread_mutex);
if (self->db_thread_terminate)
break;
if (!afsql_dd_insert_db(self))
{
afsql_dd_disconnect(self);
afsql_dd_suspend(self);
}
}
if (self->flush_lines_queued > 0)
{
/* we can't do anything with the return value here. if commit isn't
* successful, we get our backlog back, but we have no chance
* submitting that back to the SQL engine.
*/
afsql_dd_commit_txn(self, TRUE);
}
afsql_dd_disconnect(self);
msg_verbose("Database thread finished",
evt_tag_str("driver", self->super.super.id),
NULL);
return NULL;
}
static gboolean
affile_dw_reapable(AFFileDestWriter *self)
{
return log_queue_get_length(((LogWriter *) self->writer)->queue) == 0;
}
static gboolean
log_writer_fd_prepare(GSource *source,
gint *timeout)
{
LogWriterWatch *self = (LogWriterWatch *) source;
gint64 num_elements = log_queue_get_length(self->writer->queue);
GTimeVal now;
GIOCondition proto_cond;
self->pollfd.events = G_IO_ERR;
self->pollfd.revents = 0;
g_source_get_current_time(source, &now);
if (log_proto_prepare(self->proto, &self->pollfd.fd, &proto_cond, timeout))
return TRUE;
/* recalculate buckets */
if (self->writer->options->throttle > 0)
{
gint64 diff;
gint new_buckets;
/* throttling is enabled, calculate new buckets */
if (self->last_throttle_check.tv_sec != 0)
{
diff = g_time_val_diff(&now, &self->last_throttle_check);
}
else
{
diff = 0;
self->last_throttle_check = now;
}
new_buckets = (self->writer->options->throttle * diff) / G_USEC_PER_SEC;
if (new_buckets)
{
/* if new_buckets is zero, we don't save the current time as
* last_throttle_check. The reason is that new_buckets could be
* rounded to zero when only a minimal interval passes between
* poll iterations.
*/
self->writer->throttle_buckets = MIN(self->writer->options->throttle, self->writer->throttle_buckets + new_buckets);
self->last_throttle_check = now;
}
}
if (G_UNLIKELY(self->error_suspend))
{
*timeout = g_time_val_diff(&self->error_suspend_target, &now) / 1000;
if (*timeout <= 0)
{
msg_notice("Error suspend timeout has elapsed, attempting to write again",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
self->error_suspend = FALSE;
*timeout = -1;
}
else
{
return FALSE;
}
}
if ((self->writer->options->flush_lines == 0 && (!log_writer_throttling(self->writer) && num_elements != 0)) ||
(self->writer->options->flush_lines > 0 && (!log_writer_throttling(self->writer) && num_elements >= self->writer->options->flush_lines)))
{
/* we need to flush our buffers */
self->pollfd.events |= proto_cond;
}
else if (num_elements && !log_writer_throttling(self->writer))
{
/* our buffer does not contain enough elements to flush, but we do not
* want to wait more than flush_timeout time */
if (!self->flush_waiting_for_timeout)
{
/* start waiting */
*timeout = self->writer->options->flush_timeout;
g_source_get_current_time(source, &self->flush_target);
g_time_val_add(&self->flush_target, *timeout * 1000);
self->flush_waiting_for_timeout = TRUE;
}
else
{
glong to = g_time_val_diff(&self->flush_target, &now) / 1000;
if (to <= 0)
{
/* timeout elapsed, start polling again */
if (self->writer->flags & LW_ALWAYS_WRITABLE)
return TRUE;
self->pollfd.events = proto_cond;
}
else
{
*timeout = to;
}
}
return FALSE;
}
else
{
if (num_elements && log_writer_throttling(self->writer))
{
/* we are unable to send because of throttling, make sure that we
* wake up when the rate limits lets us send at least 1 message */
*timeout = (1000 / self->writer->options->throttle) + 1;
msg_debug("Throttling output",
evt_tag_int("wait", *timeout),
NULL);
}
}
if (self->writer->flags & LW_DETECT_EOF && (self->pollfd.events & G_IO_IN) == 0)
{
self->pollfd.events |= G_IO_HUP | G_IO_IN;
self->input_means_connection_broken = TRUE;
}
else
{
self->input_means_connection_broken = FALSE;
}
self->flush_waiting_for_timeout = FALSE;
if ((self->pollfd.events & G_IO_OUT) && (self->writer->flags & LW_ALWAYS_WRITABLE))
{
self->pollfd.revents = G_IO_OUT;
return TRUE;
}
return FALSE;
}
