void
test_rule_action_message_tag(const gchar *pattern, gint timeout, gint ndx, const gchar *tag, gboolean set)
{
LogMessage *msg = log_msg_new_empty();
gboolean found, result;
PDBInput input;
log_msg_set_value(msg, LM_V_MESSAGE, pattern, strlen(pattern));
log_msg_set_value(msg, LM_V_PROGRAM, "prog2", 5);
log_msg_set_value(msg, LM_V_HOST, MYHOST, strlen(MYHOST));
log_msg_set_value(msg, LM_V_PID, MYPID, strlen(MYPID));
msg->timestamps[LM_TS_STAMP].tv_sec = msg->timestamps[LM_TS_RECVD].tv_sec;
result = pattern_db_process(patterndb, PDB_INPUT_WRAP_MESSAGE(&input, msg));
if (timeout)
timer_wheel_set_time(patterndb->timer_wheel, timer_wheel_get_time(patterndb->timer_wheel) + timeout + 5);
if (ndx >= messages->len)
{
test_fail("Expected the %d. message, but no such message was returned by patterndb\n", ndx);
goto exit;
}
found = log_msg_is_tag_by_name((LogMessage *) g_ptr_array_index(messages, ndx), tag);
if (set ^ found)
test_fail("Tag '%s' is %sset for pattern '%s' (%d), index %d\n", tag, found ? "" : "not ", pattern, !!result, ndx);
exit:
log_msg_unref(msg);
test_clean_state();
}
static void
_advance_time(gint timeout)
{
if (timeout)
timer_wheel_set_time(pattern_db_get_timer_wheel(patterndb),
timer_wheel_get_time(pattern_db_get_timer_wheel(patterndb)) + timeout + 1);
}
/* NOTE: lock should be acquired for writing before calling this function. */
static void
_advance_time_based_on_message(PatternDB *self, PDBProcessParams *process_params, const LogStamp *ls)
{
GTimeVal now;
/* clamp the current time between the timestamp of the current message
* (low limit) and the current system time (high limit). This ensures
* that incorrect clocks do not skew the current time know by the
* correllation engine too much. */
cached_g_current_time(&now);
self->last_tick = now;
if (ls->tv_sec < now.tv_sec)
now.tv_sec = ls->tv_sec;
/* the expire callback uses this pointer to find the process_params it
* needs to emit messages. ProcessParams itself is a per-thread value,
* however the timer callback is executing with the writer lock held.
* There's no other mechanism to pass this pointer to the timer callback,
* so we add it to PatternDB, but make sure it is properly protected by
* locks.
* */
self->timer_process_params = process_params;
timer_wheel_set_time(self->timer_wheel, now.tv_sec);
self->timer_process_params = NULL;
msg_debug("Advancing patterndb current time because of an incoming message",
evt_tag_long("utc", timer_wheel_get_time(self->timer_wheel)));
}
static gboolean
_is_action_within_rate_limit(PatternDB *db, PDBProcessParams *process_params)
{
PDBRule *rule = process_params->rule;
PDBAction *action = process_params->action;
LogMessage *msg = process_params->msg;
GString *buffer = process_params->buffer;
CorrellationKey key;
PDBRateLimit *rl;
guint64 now;
if (action->rate == 0)
return TRUE;
g_string_printf(buffer, "%s:%d", rule->rule_id, action->id);
correllation_key_setup(&key, rule->context.scope, msg, buffer->str);
rl = g_hash_table_lookup(db->rate_limits, &key);
if (!rl)
{
rl = pdb_rate_limit_new(&key);
g_hash_table_insert(db->rate_limits, &rl->key, rl);
g_string_steal(buffer);
}
now = timer_wheel_get_time(db->timer_wheel);
if (rl->last_check == 0)
{
rl->last_check = now;
rl->buckets = action->rate;
}
else
{
/* quick and dirty fixed point arithmetic, 8 bit fraction part */
gint new_credits = (((glong) (now - rl->last_check)) << 8) / ((((glong) action->rate_quantum) << 8) / action->rate);
if (new_credits)
{
/* ok, enough time has passed to increase the current credit.
* Deposit the new credits in bucket but make sure we don't permit
* more than the maximum rate. */
rl->buckets = MIN(rl->buckets + new_credits, action->rate);
rl->last_check = now;
}
}
if (rl->buckets)
{
rl->buckets--;
return TRUE;
}
return FALSE;
}
/*
* This function can be called any time when pattern-db is not processing
* messages, but we expect the correllation timer to move forward. It
* doesn't need to be called absolutely regularly as it'll use the current
* system time to determine how much time has passed since the last
* invocation. See the timing comment at pattern_db_process() for more
* information.
*/
void
pattern_db_timer_tick(PatternDB *self)
{
GTimeVal now;
glong diff;
PDBProcessParams process_params_p = {0};
PDBProcessParams *process_params = &process_params_p;
g_static_rw_lock_writer_lock(&self->lock);
self->timer_process_params = process_params;
cached_g_current_time(&now);
diff = g_time_val_diff(&now, &self->last_tick);
if (diff > 1e6)
{
glong diff_sec = (glong) (diff / 1e6);
timer_wheel_set_time(self->timer_wheel, timer_wheel_get_time(self->timer_wheel) + diff_sec);
msg_debug("Advancing patterndb current time because of timer tick",
evt_tag_long("utc", timer_wheel_get_time(self->timer_wheel)));
/* update last_tick, take the fraction of the seconds not calculated into this update into account */
self->last_tick = now;
g_time_val_add(&self->last_tick, - (glong)(diff - diff_sec * 1e6));
}
else if (diff < 0)
{
/* time moving backwards, this can only happen if the computer's time
* is changed. We don't update patterndb's idea of the time now, wait
* another tick instead to update that instead.
*/
self->last_tick = now;
}
self->timer_process_params = NULL;
g_static_rw_lock_writer_unlock(&self->lock);
_flush_emitted_messages(self, process_params);
}
static void
_execute_action_create_context(PatternDB *db, PDBProcessParams *process_params)
{
CorrellationKey key;
PDBAction *action = process_params->action;
PDBRule *rule = process_params->rule;
PDBContext *triggering_context = process_params->context;
LogMessage *triggering_msg = process_params->msg;
GString *buffer = process_params->buffer;
PDBContext *new_context;
LogMessage *context_msg;
SyntheticContext *syn_context;
SyntheticMessage *syn_message;
syn_context = &action->content.create_context.context;
syn_message = &action->content.create_context.message;
if (triggering_context)
{
context_msg = synthetic_message_generate_with_context(syn_message, &triggering_context->super, buffer);
log_template_format_with_context(syn_context->id_template,
(LogMessage **) triggering_context->super.messages->pdata, triggering_context->super.messages->len,
NULL, LTZ_LOCAL, 0, NULL, buffer);
}
else
{
context_msg = synthetic_message_generate_without_context(syn_message, triggering_msg, buffer);
log_template_format(syn_context->id_template,
triggering_msg,
NULL, LTZ_LOCAL, 0, NULL, buffer);
}
msg_debug("Explicit create-context action, starting a new context",
evt_tag_str("rule", rule->rule_id),
evt_tag_str("context", buffer->str),
evt_tag_int("context_timeout", syn_context->timeout),
evt_tag_int("context_expiration", timer_wheel_get_time(db->timer_wheel) + syn_context->timeout));
correllation_key_setup(&key, syn_context->scope, context_msg, buffer->str);
new_context = pdb_context_new(&key);
g_hash_table_insert(db->correllation.state, &new_context->super.key, new_context);
g_string_steal(buffer);
g_ptr_array_add(new_context->super.messages, context_msg);
new_context->super.timer = timer_wheel_add_timer(db->timer_wheel, rule->context.timeout, pattern_db_expire_entry,
correllation_context_ref(&new_context->super),
(GDestroyNotify) correllation_context_unref);
new_context->rule = pdb_rule_ref(rule);
}
void
pattern_db_advance_time(PatternDB *self, gint timeout)
{
PDBProcessParams process_params_p = {0};
PDBProcessParams *process_params = &process_params_p;
time_t new_time;
g_static_rw_lock_writer_lock(&self->lock);
new_time = timer_wheel_get_time(self->timer_wheel) + timeout;
self->timer_process_params = process_params;
timer_wheel_set_time(self->timer_wheel, new_time);
self->timer_process_params = NULL;
g_static_rw_lock_writer_unlock(&self->lock);
_flush_emitted_messages(self, process_params);
}
void
test_rule_action_message_value(const gchar *pattern, gint timeout, gint ndx, const gchar *name, const gchar *value)
{
LogMessage *msg = log_msg_new_empty();
gboolean found = FALSE, result;
const gchar *val;
gssize len;
PDBInput input;
log_msg_set_value(msg, LM_V_MESSAGE, pattern, strlen(pattern));
log_msg_set_value(msg, LM_V_PROGRAM, "prog2", 5);
log_msg_set_value(msg, LM_V_HOST, MYHOST, strlen(MYHOST));
log_msg_set_value(msg, LM_V_PID, MYPID, strlen(MYPID));
msg->timestamps[LM_TS_STAMP].tv_sec = msg->timestamps[LM_TS_RECVD].tv_sec;
result = pattern_db_process(patterndb, PDB_INPUT_WRAP_MESSAGE(&input, msg));
if (timeout)
timer_wheel_set_time(patterndb->timer_wheel, timer_wheel_get_time(patterndb->timer_wheel) + timeout + 1);
if (ndx >= messages->len)
{
test_fail("Expected the %d. message, but no such message was returned by patterndb\n", ndx);
goto exit;
}
val = log_msg_get_value((LogMessage *) g_ptr_array_index(messages, ndx), log_msg_get_value_handle(name), &len);
if (value)
found = strcmp(val, value) == 0;
if (!!value ^ (len > 0))
test_fail("Value '%s' is %smatching for pattern '%s' (%d) index %d\n", name, found ? "" : "not ", pattern, !!result, ndx);
exit:
log_msg_unref(msg);
test_clean_state();
}
static void
pattern_db_expire_entry(TimerWheel *wheel, guint64 now, gpointer user_data)
{
PDBContext *context = user_data;
PatternDB *pdb = (PatternDB *) timer_wheel_get_associated_data(wheel);
GString *buffer = g_string_sized_new(256);
LogMessage *msg = correllation_context_get_last_message(&context->super);
PDBProcessParams *process_params = pdb->timer_process_params;
msg_debug("Expiring patterndb correllation context",
evt_tag_str("last_rule", context->rule->rule_id),
evt_tag_long("utc", timer_wheel_get_time(pdb->timer_wheel)));
process_params->context = context;
process_params->rule = context->rule;
process_params->msg = msg;
process_params->buffer = buffer;
_execute_rule_actions(pdb, process_params, RAT_TIMEOUT);
g_hash_table_remove(pdb->correllation.state, &context->super.key);
g_string_free(buffer, TRUE);
/* pdb_context_free is automatically called when returning from
this function by the timerwheel code as a destroy notify
callback. */
}
static void
_advance_time(gint timeout)
{
if (timeout)
timer_wheel_set_time(patterndb->timer_wheel, timer_wheel_get_time(patterndb->timer_wheel) + timeout + 1);
}
static void
_pattern_db_process_matching_rule(PatternDB *self, PDBProcessParams *process_params)
{
PDBContext *context = NULL;
PDBRule *rule = process_params->rule;
LogMessage *msg = process_params->msg;
GString *buffer = g_string_sized_new(32);
g_static_rw_lock_writer_lock(&self->lock);
_advance_time_based_on_message(self, process_params, &msg->timestamps[LM_TS_STAMP]);
if (rule->context.id_template)
{
CorrellationKey key;
log_template_format(rule->context.id_template, msg, NULL, LTZ_LOCAL, 0, NULL, buffer);
log_msg_set_value(msg, context_id_handle, buffer->str, -1);
correllation_key_setup(&key, rule->context.scope, msg, buffer->str);
context = g_hash_table_lookup(self->correllation.state, &key);
if (!context)
{
msg_debug("Correllation context lookup failure, starting a new context",
evt_tag_str("rule", rule->rule_id),
evt_tag_str("context", buffer->str),
evt_tag_int("context_timeout", rule->context.timeout),
evt_tag_int("context_expiration", timer_wheel_get_time(self->timer_wheel) + rule->context.timeout));
context = pdb_context_new(&key);
g_hash_table_insert(self->correllation.state, &context->super.key, context);
g_string_steal(buffer);
}
else
{
msg_debug("Correllation context lookup successful",
evt_tag_str("rule", rule->rule_id),
evt_tag_str("context", buffer->str),
evt_tag_int("context_timeout", rule->context.timeout),
evt_tag_int("context_expiration", timer_wheel_get_time(self->timer_wheel) + rule->context.timeout),
evt_tag_int("num_messages", context->super.messages->len));
}
g_ptr_array_add(context->super.messages, log_msg_ref(msg));
if (context->super.timer)
{
timer_wheel_mod_timer(self->timer_wheel, context->super.timer, rule->context.timeout);
}
else
{
context->super.timer = timer_wheel_add_timer(self->timer_wheel, rule->context.timeout, pattern_db_expire_entry,
correllation_context_ref(&context->super),
(GDestroyNotify) correllation_context_unref);
}
if (context->rule != rule)
{
if (context->rule)
pdb_rule_unref(context->rule);
context->rule = pdb_rule_ref(rule);
}
}
else
{
context = NULL;
}
process_params->context = context;
process_params->buffer = buffer;
synthetic_message_apply(&rule->msg, &context->super, msg, buffer);
_emit_message(self, process_params, FALSE, msg);
_execute_rule_actions(self, process_params, RAT_MATCH);
pdb_rule_unref(rule);
g_static_rw_lock_writer_unlock(&self->lock);
if (context)
log_msg_write_protect(msg);
g_string_free(buffer, TRUE);
}