Test(logthrdestdrv,
when_batched_set_of_messages_result_in_error_the_entire_batch_is_attempted_again_retry_count_times_and_then_dropped)
{
dd->super.worker.insert = _insert_batched_message_error_drop;
dd->super.worker.flush = _flush_batched_message_error_drop;
dd->super.time_reopen = 0;
dd->super.retries_on_error_max = 5;
start_grabbing_messages();
_generate_messages_and_wait_for_processing(dd, 10, dd->super.dropped_messages);
cr_assert(dd->insert_counter == dd->super.retries_on_error_max * 10,
"not all messages were attempted %d times, insert_counter=%d", dd->super.retries_on_error_max, dd->insert_counter);
cr_assert(dd->flush_size == dd->super.retries_on_error_max * 10,
"not all messages were flushed %d times, flush_size=%d", dd->super.retries_on_error_max, dd->flush_size);
cr_assert(stats_counter_get(dd->super.processed_messages) == 10);
cr_assert(stats_counter_get(dd->super.written_messages) == 0);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 10);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == dd->super.retries_on_error_max * 10 + 1,
"seq_num needs to be one larger than the number of insert attempts, found %d", dd->super.shared_seq_num);
assert_grabbed_log_contains("Error occurred while");
assert_grabbed_log_contains("Multiple failures while sending");
}
Test(logthrdestdrv,
when_batched_set_of_messages_result_in_not_connected_the_entire_batch_is_attempted_again_and_then_successfully_delivered)
{
gint total_attempts = FAILING_ATTEMPTS_NOTCONN + 1;
dd->super.worker.insert = _insert_batched_message_not_connected;
dd->super.worker.flush = _flush_batched_message_not_connected;
dd->super.time_reopen = 0;
dd->super.retries_on_error_max = 5;
start_grabbing_messages();
_generate_messages_and_wait_for_processing(dd, 10, dd->super.written_messages);
cr_assert(dd->insert_counter == total_attempts * 10,
"not all messages were attempted %d times, insert_counter=%d", total_attempts, dd->insert_counter);
cr_assert(dd->flush_size == total_attempts * 10,
"not all messages were flushed %d times, flush_size=%d", total_attempts, dd->flush_size);
cr_assert(stats_counter_get(dd->super.processed_messages) == 10);
cr_assert(stats_counter_get(dd->super.written_messages) == 10);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == total_attempts * 10 + 1, "%d", dd->super.shared_seq_num);
assert_grabbed_log_contains("Server disconnected");
}
Test(logthrdestdrv, throttle_is_applied_to_delivery_and_causes_flush_to_be_called_more_often)
{
/* 3 messages per second, we need to set this explicitly on the queue as it has already been initialized */
log_queue_set_throttle(dd->super.worker.instance.queue, 3);
dd->super.worker.insert = _insert_batched_message_success;
dd->super.worker.flush = _flush_batched_message_success;
dd->super.batch_lines = 5;
start_stopwatch();
_generate_messages_and_wait_for_processing(dd, 20, dd->super.written_messages);
guint64 time_msec = stop_stopwatch_and_get_result();
/* NOTE: initially we send a bucket worth of messages, and then pace out
* the remaining 6 buckets 1sec apart */
cr_assert(time_msec > 5000000);
cr_assert(dd->insert_counter == 20);
cr_assert(dd->flush_size == 20);
cr_assert(dd->flush_counter > 3);
cr_assert(stats_counter_get(dd->super.processed_messages) == 20);
cr_assert(stats_counter_get(dd->super.written_messages) == 20);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == 21, "%d", dd->super.shared_seq_num);
}
Test(scratch_buffers, stats_counters_are_updated)
{
GString *str;
for (gint count = 1; count <= ITERATIONS; count++)
{
str = scratch_buffers_alloc();
cr_assert_not_null(str);
/* check through accessor functions */
cr_assert(scratch_buffers_get_local_usage_count() == count,
"get_local_usage_count() not returning proper value, value=%d, expected=%d",
scratch_buffers_get_local_usage_count(), count);
cr_assert(scratch_buffers_get_local_allocation_bytes() == count * DEFAULT_ALLOC_SIZE,
"get_local_allocation_bytes() not returning proper value, value=%ld, expected=%ld",
scratch_buffers_get_local_allocation_bytes(), count * DEFAULT_ALLOC_SIZE);
/* check through metrics */
cr_assert(stats_counter_get(stats_scratch_buffers_count) == count,
"Statistic scratch_buffers_count is not updated properly, value=%d, expected=%d",
(gint) stats_counter_get(stats_scratch_buffers_count), count);
/* check if byte counter is updated */
scratch_buffers_update_stats();
cr_assert_eq(stats_counter_get(stats_scratch_buffers_bytes), count * DEFAULT_ALLOC_SIZE);
}
}
Test(logthrdestdrv, driver_can_be_instantiated_and_one_message_is_properly_processed)
{
dd->super.worker.insert = _insert_single_message_success;
_generate_message_and_wait_for_processing(dd, dd->super.written_messages);
cr_assert(dd->insert_counter == 1,
"insert()-ed message count expected to match the amount generated, found %d", dd->insert_counter);
cr_assert(stats_counter_get(dd->super.processed_messages) == 1);
cr_assert(stats_counter_get(dd->super.written_messages) == 1);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == 2,
"seq_num expected to be 1 larger than the amount of messages generated, found %d", dd->super.shared_seq_num);
}
static void
stats_format_csv(StatsCluster *sc, gint type, StatsCounterItem *counter, gpointer user_data)
{
GString *csv = (GString *) user_data;
gchar *s_id, *s_instance, *tag_name;
gchar buf[32];
gchar state;
s_id = stats_format_csv_escapevar(sc->key.id);
s_instance = stats_format_csv_escapevar(sc->key.instance);
if (sc->dynamic)
state = 'd';
else if (sc->use_count == 0)
state = 'o';
else
state = 'a';
tag_name = stats_format_csv_escapevar(stats_cluster_get_type_name(sc, type));
g_string_append_printf(csv, "%s;%s;%s;%c;%s;%"G_GSIZE_FORMAT"\n",
stats_cluster_get_component_name(sc, buf, sizeof(buf)),
s_id, s_instance, state, tag_name, stats_counter_get(&sc->counter_group.counters[type]));
g_free(tag_name);
g_free(s_id);
g_free(s_instance);
}
Test(logthrdestdrv, message_drops_are_accounted_in_the_drop_counter_and_are_reported_properly)
{
dd->super.worker.insert = _insert_single_message_drop;
start_grabbing_messages();
_generate_message_and_wait_for_processing(dd, dd->super.dropped_messages);
cr_assert(dd->insert_counter == 1,
"insert()-ed message count expected to match the amount generated, found %d", dd->insert_counter);
cr_assert(stats_counter_get(dd->super.processed_messages) == 1);
cr_assert(stats_counter_get(dd->super.written_messages) == 0);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 1);
cr_assert(dd->super.shared_seq_num == 2,
"seq_num expected to be 1 larger than the amount of messages generated, found %d", dd->super.shared_seq_num);
assert_grabbed_log_contains("dropped while sending");
}
static void
_spin_for_counter_value(StatsCounterItem *counter, gssize expected_value)
{
gssize value = stats_counter_get(counter);
gint c = 0;
while (value != expected_value && c < MAX_SPIN_ITERATIONS)
{
value = stats_counter_get(counter);
_sleep_msec(1);
c++;
}
cr_assert(expected_value == value,
"counter did not reach the expected value after %d seconds, "
"expected_value=%" G_GSSIZE_FORMAT ", value=%" G_GSSIZE_FORMAT,
MAX_SPIN_ITERATIONS / 1000, expected_value, value);
}
Test(logthrdestdrv, test_explicit_ack_accept)
{
dd->super.worker.insert = _insert_explicit_acks_message_success;
dd->super.worker.flush = _flush_explicit_acks_message_success;
dd->super.batch_lines = 5;
_generate_messages_and_wait_for_processing(dd, 10, dd->super.written_messages);
cr_assert(dd->insert_counter == 10, "%d", dd->insert_counter);
cr_assert(dd->flush_size == 10);
cr_assert(stats_counter_get(dd->super.processed_messages) == 10);
cr_assert(stats_counter_get(dd->super.written_messages) == 10);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->queued_messages) == 0);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == 11, "%d", dd->super.shared_seq_num);
}
Test(logthrdestdrv, connection_failure_is_considered_an_error_and_retried_indefinitely)
{
dd->super.worker.insert = _insert_single_message_connection_failure;
dd->super.time_reopen = 0;
start_grabbing_messages();
_generate_message_and_wait_for_processing(dd, dd->super.written_messages);
cr_assert(dd->insert_counter == 11,
"insert() invocations expected to match 11 (10 failed and 1 successul) attempts, found %d", dd->insert_counter);
cr_assert(stats_counter_get(dd->super.processed_messages) == 1);
cr_assert(stats_counter_get(dd->super.written_messages) == 1);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(dd->super.shared_seq_num == 12,
"seq_num expected to be 1 larger than the number of insert attempts, found %d", dd->super.shared_seq_num);
assert_grabbed_log_contains("Server disconnected");
}
Test(logthrdestdrv, batched_set_of_messages_are_dropped_as_a_whole)
{
dd->super.worker.insert = _insert_batched_message_drop;
dd->super.worker.flush = _flush_batched_message_drop;
dd->super.time_reopen = 0;
start_grabbing_messages();
_generate_messages_and_wait_for_processing(dd, 10, dd->super.dropped_messages);
cr_assert(dd->insert_counter == 10);
cr_assert(dd->flush_size == 10);
cr_assert(stats_counter_get(dd->super.processed_messages) == 10);
cr_assert(stats_counter_get(dd->super.written_messages) == 0);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 10);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == 11, "%d", dd->super.shared_seq_num);
assert_grabbed_log_contains("dropped while sending message");
}
Test(logthrdestdrv, batched_set_of_messages_are_successfully_delivered)
{
dd->super.worker.insert = _insert_batched_message_success;
dd->super.worker.flush = _flush_batched_message_success;
dd->super.batch_lines = 5;
_generate_messages_and_wait_for_processing(dd, 10, dd->super.written_messages);
cr_assert(dd->insert_counter == 10,
"insert() invocations expected to match the number of messages generated, found %d", dd->insert_counter);
cr_assert(dd->flush_size == 10,
"flush_size expected to match the number of messages generated, found %d", dd->flush_size);
cr_assert(stats_counter_get(dd->super.processed_messages) == 10);
cr_assert(stats_counter_get(dd->super.written_messages) == 10);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(stats_counter_get(dd->super.worker.instance.queue->memory_usage) == 0);
cr_assert(dd->super.shared_seq_num == 11,
"seq_num expected to be 1 larger than the number of insert attempts, found %d", dd->super.shared_seq_num);
}
Test(logthrdestdrv, error_result_retries_sending_retry_max_times_and_then_accepts)
{
dd->super.worker.insert = _insert_single_message_error_until_successful;
dd->super.time_reopen = 0;
dd->super.retries_on_error_max = 5;
start_grabbing_messages();
_generate_message_and_wait_for_processing(dd, dd->super.written_messages);
cr_assert(dd->insert_counter == 5,
"insert() invocations expected to match the number of failed (4) plus the number of successful (1) attempts, found %d",
dd->insert_counter);
cr_assert(stats_counter_get(dd->super.processed_messages) == 1);
cr_assert(stats_counter_get(dd->super.written_messages) == 1);
cr_assert(stats_counter_get(dd->super.dropped_messages) == 0);
cr_assert(dd->super.shared_seq_num == 6,
"seq_num expected to be 1 larger than the number of insert attempts, found %d", dd->super.shared_seq_num);
assert_grabbed_log_contains("Error occurred while");
}
Test(logqueue, test_zero_diskbuf_and_normal_acks)
{
LogQueue *q;
gint i;
q = log_queue_fifo_new(OVERFLOW_SIZE, NULL);
StatsClusterKey sc_key;
stats_lock();
stats_cluster_logpipe_key_set(&sc_key, SCS_DESTINATION, q->persist_name, NULL );
stats_register_counter(0, &sc_key, SC_TYPE_QUEUED, &q->queued_messages);
stats_register_counter(1, &sc_key, SC_TYPE_MEMORY_USAGE, &q->memory_usage);
stats_unlock();
log_queue_set_use_backlog(q, TRUE);
cr_assert_eq(atomic_gssize_racy_get(&q->queued_messages->value), 0);
fed_messages = 0;
acked_messages = 0;
feed_some_messages(q, 1);
cr_assert_eq(stats_counter_get(q->queued_messages), 1);
cr_assert_neq(stats_counter_get(q->memory_usage), 0);
gint size_when_single_msg = stats_counter_get(q->memory_usage);
for (i = 0; i < 10; i++)
feed_some_messages(q, 10);
cr_assert_eq(stats_counter_get(q->queued_messages), 101);
cr_assert_eq(stats_counter_get(q->memory_usage), 101*size_when_single_msg);
send_some_messages(q, fed_messages);
log_queue_ack_backlog(q, fed_messages);
cr_assert_eq(fed_messages, acked_messages,
"did not receive enough acknowledgements: fed_messages=%d, acked_messages=%d",
fed_messages, acked_messages);
log_queue_unref(q);
}
void
_sum_selected_counters(GList *counters, gpointer user_data)
{
GList *c;
gpointer *args = (gpointer *) user_data;
gint64 *sum = (gint64 *) args[1];
for (c = counters; c; c = c->next)
{
StatsCounterItem *counter = c->data;
if (!_is_timestamp(stats_counter_get_name(counter)))
*sum += stats_counter_get(counter);
}
}
static void
stats_log_format_counter(StatsCluster *sc, gint type, StatsCounterItem *item, gpointer user_data)
{
EVTREC *e = (EVTREC *) user_data;
EVTTAG *tag;
gchar buf[32];
tag = evt_tag_printf(stats_cluster_get_type_name(type), "%s(%s%s%s)=%u",
stats_cluster_get_component_name(sc, buf, sizeof(buf)),
sc->id,
(sc->id[0] && sc->instance[0]) ? "," : "",
sc->instance,
stats_counter_get(&sc->counters[type]));
evt_rec_add_tag(e, tag);
}
Test(logqueue, log_queue_fifo_rewind_all_and_memory_usage)
{
LogQueue *q = log_queue_fifo_new(OVERFLOW_SIZE, NULL);
log_queue_set_use_backlog(q, TRUE);
StatsClusterKey sc_key;
stats_lock();
stats_cluster_logpipe_key_set(&sc_key, SCS_DESTINATION, q->persist_name, NULL );
stats_register_counter(1, &sc_key, SC_TYPE_MEMORY_USAGE, &q->memory_usage);
stats_unlock();
feed_some_messages(q, 1);
gint size_when_single_msg = stats_counter_get(q->memory_usage);
feed_some_messages(q, 9);
cr_assert_eq(stats_counter_get(q->memory_usage), 10*size_when_single_msg);
send_some_messages(q, 10);
cr_assert_eq(stats_counter_get(q->memory_usage), 0);
log_queue_rewind_backlog_all(q);
cr_assert_eq(stats_counter_get(q->memory_usage), 10*size_when_single_msg);
log_queue_unref(q);
}
