Test(linux_kmsg_format, test_kmsg_with_extra_fields)
{
gchar msg[] = "5,2,0,some extra field,3,4,5;And this is the real message\n";
LogMessage *parsed_message;
parsed_message = kmsg_parse_message(msg);
cr_assert_eq(parsed_message->pri, 5, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "2");
assert_log_message_value(parsed_message, LM_V_MESSAGE, "And this is the real message");
log_msg_unref(parsed_message);
}
static void
test_kv_parser_basics(void)
{
LogMessage *msg;
msg = parse_kv_into_log_message("foo=bar");
assert_log_message_value(msg, log_msg_get_value_handle("foo"), "bar");
log_msg_unref(msg);
kv_parser_set_prefix(kv_parser, ".prefix.");
msg = parse_kv_into_log_message("foo=bar");
assert_log_message_value(msg, log_msg_get_value_handle(".prefix.foo"), "bar");
log_msg_unref(msg);
}
static void
test_geoip_parser_basics(void)
{
LogMessage *msg;
msg = parse_geoip_into_log_message("217.20.130.99");
assert_log_message_value(msg, log_msg_get_value_handle(".geoip.country_code"), "HU");
log_msg_unref(msg);
geoip_parser_set_prefix(geoip_parser, ".prefix.");
msg = parse_geoip_into_log_message("217.20.130.99");
assert_log_message_value(msg, log_msg_get_value_handle(".prefix.country_code"), "HU");
log_msg_unref(msg);
}
void
test_log_messages_can_be_parsed(struct msgparse_params *param)
{
LogMessage *parsed_message;
LogStamp *parsed_timestamp;
time_t now;
GString *sd_str;
parsed_message = _parse_log_message(param->msg, param->parse_flags, param->bad_hostname_re);
parsed_timestamp = &(parsed_message->timestamps[LM_TS_STAMP]);
if (param->expected_stamp_sec)
{
if (param->expected_stamp_sec != 1)
cr_assert_eq(parsed_timestamp->tv_sec, param->expected_stamp_sec,
"Unexpected timestamp, value=%ld, expected=%ld, msg=%s",
parsed_timestamp->tv_sec, param->expected_stamp_sec, param->msg);
cr_assert_eq(parsed_timestamp->tv_usec, param->expected_stamp_usec, "Unexpected microseconds");
cr_assert_eq(parsed_timestamp->zone_offset, param->expected_stamp_ofs, "Unexpected timezone offset");
}
else
{
time(&now);
cr_assert(_absolute_value(parsed_timestamp->tv_sec - now) <= 5,
"Expected parsed message timestamp to be set to now; now='%d', timestamp->tv_sec='%d'",
(gint)now, (gint)parsed_timestamp->tv_sec);
}
cr_assert_eq(parsed_message->pri, param->expected_pri, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_HOST, param->expected_host);
assert_log_message_value(parsed_message, LM_V_PROGRAM, param->expected_program);
assert_log_message_value(parsed_message, LM_V_MESSAGE, param->expected_msg);
if (param->expected_pid)
assert_log_message_value(parsed_message, LM_V_PID, param->expected_pid);
if (param->expected_msgid)
assert_log_message_value(parsed_message, LM_V_MSGID, param->expected_msgid);
if (param->expected_sd_str)
{
sd_str = g_string_sized_new(0);
log_msg_format_sdata(parsed_message, sd_str, 0);
cr_assert_str_eq(sd_str->str, param->expected_sd_str, "Unexpected formatted SData");
g_string_free(sd_str, TRUE);
}
assert_log_message_sdata_pairs(parsed_message, param->expected_sd_pairs);
log_msg_unref(parsed_message);
}
Test(linux_kmsg_format, test_kmsg_single_line)
{
gchar msg[] =
"5,2,1;Linux version 3.5-trunk-amd64 (Debian 3.5.2-1~experimental.1) ([email protected]) (gcc version 4.6.3 (Debian 4.6.3-1) ) #1 SMP Mon Aug 20 04:17:46 UTC 2012\n";
LogMessage *parsed_message;
parsed_message = kmsg_parse_message(msg);
cr_assert_eq(parsed_message->pri, 5, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "2");
msg[sizeof(msg) - 2] = '\0';
assert_log_message_value(parsed_message, LM_V_MESSAGE, msg + 6);
assert_log_kmsg_value(parsed_message, ".linux.timestamp", "1");
log_msg_unref(parsed_message);
}
void
test_kmsg_with_extra_fields(void)
{
gchar msg[] = "5,2,0,some extra field,3,4,5;And this is the real message\n";
LogMessage *parsed_message;
testcase_begin("Testing /dev/kmsg parsing, with extra fields; msg='%s'", msg);
parsed_message = kmsg_parse_message(msg);
assert_guint16(parsed_message->pri, 5, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "2");
assert_log_message_value(parsed_message, LM_V_MESSAGE, "And this is the real message");
log_msg_unref(parsed_message);
testcase_end();
}
Test(linux_kmsg_format, test_kmsg_multi_line)
{
gchar msg[] = "6,202,98513;pci_root PNP0A08:00: host bridge window [io 0x0000-0x0cf7]\n" \
" SUBSYSTEM=acpi\n" \
" DEVICE=+acpi:PNP0A08:00\n";
LogMessage *parsed_message;
parsed_message = kmsg_parse_message(msg);
cr_assert_eq(parsed_message->pri, 6, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "202");
assert_log_message_value(parsed_message, LM_V_MESSAGE, "pci_root PNP0A08:00: host bridge window [io 0x0000-0x0cf7]");
assert_log_kmsg_value(parsed_message, ".linux.SUBSYSTEM", "acpi");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "acpi");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.name", "PNP0A08:00");
log_msg_unref(parsed_message);
}
void
assert_new_log_message_attributes(LogMessage *log_message)
{
assert_log_message_value(log_message, LM_V_HOST, "newhost");
assert_log_message_value(log_message, LM_V_HOST_FROM, "newhost");
assert_log_message_value(log_message, LM_V_MESSAGE, "newmsg");
assert_log_message_value(log_message, LM_V_PROGRAM, "newprogram");
assert_log_message_value(log_message, LM_V_PID, "newpid");
assert_log_message_value(log_message, LM_V_MSGID, "newmsgid");
assert_log_message_value(log_message, LM_V_SOURCE, "newsource");
assert_log_message_value(log_message, log_msg_get_value_handle("newvalue"), "newvalue");
}
void
test_kmsg_single_line(void)
{
gchar msg[] = "5,2,1;Linux version 3.5-trunk-amd64 (Debian 3.5.2-1~experimental.1) ([email protected]) (gcc version 4.6.3 (Debian 4.6.3-1) ) #1 SMP Mon Aug 20 04:17:46 UTC 2012\n";
LogMessage *parsed_message;
testcase_begin("Testing single-line /dev/kmsg parsing; msg='%s'", msg);
parsed_message = kmsg_parse_message(msg);
assert_guint16(parsed_message->pri, 5, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "2");
msg[sizeof(msg) - 2] = '\0';
assert_log_message_value(parsed_message, LM_V_MESSAGE, msg + 6);
assert_log_kmsg_value(parsed_message, ".linux.timestamp", "1");
log_msg_unref(parsed_message);
testcase_end();
}
static void
assert_msg_doesnot_match(const gchar *message)
{
LogMessage *msg;
gboolean result;
msg = _construct_message("prog1", message);
result = _process(msg);
assert_false(result, "patterndb expected to match but it didn't");
assert_log_message_value(msg, log_msg_get_value_handle(".classifier.class"), "unknown");
assert_log_message_has_tag(msg, ".classifier.unknown");
log_msg_unref(msg);
}
static void
assert_msg_with_program_matches_and_nvpair_equals(const gchar *program, const gchar *message,
const gchar *name, const gchar *expected_value)
{
LogMessage *msg;
gboolean result;
msg = _construct_message(program, message);
result = _process(msg);
assert_true(result, "patterndb expected to match but it didn't");
assert_log_message_value(msg, log_msg_get_value_handle(name), expected_value);
log_msg_unref(msg);
}
void
test_kmsg_multi_line(void)
{
gchar msg[] = "6,202,98513;pci_root PNP0A08:00: host bridge window [io 0x0000-0x0cf7]\n" \
" SUBSYSTEM=acpi\n" \
" DEVICE=+acpi:PNP0A08:00\n";
LogMessage *parsed_message;
testcase_begin("Testing multi-line /dev/kmsg parsing; msg='%s'", msg);
parsed_message = kmsg_parse_message(msg);
assert_guint16(parsed_message->pri, 6, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_MSGID, "202");
assert_log_message_value(parsed_message, LM_V_MESSAGE, "pci_root PNP0A08:00: host bridge window [io 0x0000-0x0cf7]");
assert_log_kmsg_value(parsed_message, ".linux.SUBSYSTEM", "acpi");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "acpi");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.name", "PNP0A08:00");
log_msg_unref(parsed_message);
testcase_end();
}
Test(linux_kmsg_format, test_kmsg_device_parsing)
{
gchar msg_subsys[] = "6,202,98513;pci_root PNP0A08:00: host bridge window [io 0x0000-0x0cf7]\n" \
" SUBSYSTEM=acpi\n" \
" DEVICE=+acpi:PNP0A08:00\n";
gchar msg_block[] = "6,202,98513;Fake message\n" \
" DEVICE=b12:1\n";
gchar msg_char[] = "6,202,98513;Fake message\n" \
" DEVICE=c3:4\n";
gchar msg_netdev[] = "6,202,98513;Fake message\n" \
" DEVICE=n8\n";
gchar msg_unknown[] = "6,202,98513;Fake message\n" \
" DEVICE=w12345\n";
gchar msg_invalid_block[] = "6,202;Fake message\n" \
" DEVICE=b12:1\n";
LogMessage *parsed_message;
parsed_message = kmsg_parse_message(msg_subsys);
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "acpi");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.name", "PNP0A08:00");
log_msg_unref(parsed_message);
parsed_message = kmsg_parse_message(msg_block);
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "block");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.major", "12");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.minor", "1");
log_msg_unref(parsed_message);
parsed_message = kmsg_parse_message(msg_char);
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "char");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.major", "3");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.minor", "4");
log_msg_unref(parsed_message);
parsed_message = kmsg_parse_message(msg_netdev);
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "netdev");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.index", "8");
log_msg_unref(parsed_message);
parsed_message = kmsg_parse_message(msg_unknown);
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.type", "<unknown>");
assert_log_kmsg_value(parsed_message, ".linux.DEVICE.name", "w12345");
log_msg_unref(parsed_message);
parsed_message = kmsg_parse_message(msg_invalid_block);
assert_log_message_value(parsed_message, LM_V_MESSAGE,
"Error processing log message: 6,202>@<;Fake message\n DEVICE=b12:1");
log_msg_unref(parsed_message);
}
void
assert_output_message_nvpair_equals(gint ndx, const gchar *name, const gchar *value)
{
assert_log_message_value(_get_output_message(ndx), log_msg_get_value_handle(name), value);
}
void
testcase(gchar *msg,
gint parse_flags,
gchar *bad_hostname_re,
gint expected_pri,
unsigned long expected_stamp_sec,
unsigned long expected_stamp_usec,
unsigned long expected_stamp_ofs,
const gchar *expected_host,
const gchar *expected_program,
const gchar *expected_msg,
const gchar *expected_sd_str,
const gchar *expected_pid,
const gchar *expected_msgid,
const gchar *expected_sd_pairs[][2])
{
LogMessage *parsed_message;
LogStamp *parsed_timestamp;
time_t now;
GString *sd_str;
testcase_begin("Testing log message parsing; parse_flags='%x', bad_hostname_re='%s', msg='%s'",
parse_flags, bad_hostname_re ? : "(null)", msg);
parsed_message = parse_log_message(msg, parse_flags, bad_hostname_re);
parsed_timestamp = &(parsed_message->timestamps[LM_TS_STAMP]);
if (expected_stamp_sec)
{
if (expected_stamp_sec != 1)
assert_guint(parsed_timestamp->tv_sec, expected_stamp_sec, "Unexpected timestamp");
assert_guint32(parsed_timestamp->tv_usec, expected_stamp_usec, "Unexpected microseconds");
assert_guint32(parsed_timestamp->zone_offset, expected_stamp_ofs, "Unexpected timezone offset");
}
else
{
time(&now);
assert_true(absolute_value(parsed_timestamp->tv_sec - now) <= 5,
"Expected parsed message timestamp to be set to now; now='%d', timestamp->tv_sec='%d'",
(gint)now, (gint)parsed_timestamp->tv_sec, NULL);
}
assert_guint16(parsed_message->pri, expected_pri, "Unexpected message priority");
assert_log_message_value(parsed_message, LM_V_HOST, expected_host);
assert_log_message_value(parsed_message, LM_V_PROGRAM, expected_program);
assert_log_message_value(parsed_message, LM_V_MESSAGE, expected_msg);
if (expected_pid)
assert_log_message_value(parsed_message, LM_V_PID, expected_pid);
if (expected_msgid)
assert_log_message_value(parsed_message, LM_V_MSGID, expected_msgid);
if (expected_sd_str)
{
sd_str = g_string_sized_new(0);
log_msg_format_sdata(parsed_message, sd_str, 0);
assert_string(sd_str->str, expected_sd_str, "Unexpected formatted SData");
g_string_free(sd_str, TRUE);
}
assert_log_message_sdata_pairs(parsed_message, expected_sd_pairs);
log_msg_unref(parsed_message);
testcase_end();
}
void
assert_log_message_value_by_name(LogMessage *self, const gchar *name, const gchar *expected_value)
{
assert_log_message_value(self, log_msg_get_value_handle(name), expected_value);
}
