/*
* NOTE: suppress_lock must be held.
*/
static void
log_writer_emit_suppress_summary(LogWriter *self)
{
LogMessage *m;
LogPathOptions path_options = LOG_PATH_OPTIONS_INIT;
gchar buf[1024];
gssize len;
const gchar *p;
msg_debug("Suppress timer elapsed, emitting suppression summary",
NULL);
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, suppressed by syslog-ng on %s",
log_msg_get_value(self->last_msg, LM_V_MESSAGE, NULL),
self->last_msg_count,
get_local_hostname_fqdn());
log_msg_set_value(m, LM_V_MESSAGE, buf, len);
path_options.ack_needed = FALSE;
log_queue_push_tail(self->queue, m, &path_options);
log_writer_release_last_message(self);
}
/**
* 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;
}
/**
* 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;
}
