test: improve debug logging for the integration tests

Visually easier to get a grasp on what's happening now.

Signed-off-by: Peter Hutterer <peter.hutterer@who-t.net>
This commit is contained in:
Peter Hutterer 2020-09-23 14:18:12 +10:00
parent 003075c013
commit f6f8aa1fd1
2 changed files with 137 additions and 23 deletions

View file

@ -24,6 +24,7 @@
#include "config.h"
#include <stdlib.h>
#include <stdio.h>
#include <sys/socket.h>
#include <munit.h>
@ -45,8 +46,27 @@ struct peck {
uint32_t eis_behavior;
uint32_t ei_behavior;
struct logger *logger;
uint32_t indent;
};
static const uint32_t INDENTATION = 4;
static void
peck_indent(struct peck *peck)
{
peck->indent += INDENTATION;
}
static void
peck_dedent(struct peck *peck)
{
assert(peck->indent >= INDENTATION);
peck->indent -= INDENTATION;
}
static
OBJECT_IMPLEMENT_GETTER(peck, indent, uint32_t);
static void
peck_destroy(struct peck *peck)
{
@ -66,6 +86,79 @@ OBJECT_IMPLEMENT_UNREF(peck);
OBJECT_IMPLEMENT_GETTER(peck, ei, struct ei*);
OBJECT_IMPLEMENT_GETTER(peck, eis, struct eis*);
static void
peck_ei_log_handler(struct ei *ei,
enum ei_log_priority priority,
const char *message,
bool is_continuation)
{
if (is_continuation) {
fprintf(stderr, "%s", message);
return;
}
const char *prefix = NULL;
switch (priority) {
case EI_LOG_PRIORITY_ERROR: prefix = "ERR"; break;
case EI_LOG_PRIORITY_WARNING: prefix = "WRN"; break;
case EI_LOG_PRIORITY_INFO: prefix = "INF"; break;
case EI_LOG_PRIORITY_DEBUG: prefix = "DBG"; break;
}
struct peck *peck = ei_get_user_data(ei);
fprintf(stderr, "| | ei | | %s |%*s🥚 %s",
prefix, peck_get_indent(peck), " ", message);
}
static void
peck_eis_log_handler(struct eis *eis,
enum eis_log_priority priority,
const char *message,
bool is_continuation)
{
if (is_continuation) {
fprintf(stderr, "%s", message);
return;
}
const char *prefix = NULL;
switch (priority) {
case EIS_LOG_PRIORITY_ERROR: prefix = "ERR"; break;
case EIS_LOG_PRIORITY_WARNING: prefix = "WRN"; break;
case EIS_LOG_PRIORITY_INFO: prefix = "INF"; break;
case EIS_LOG_PRIORITY_DEBUG: prefix = "DBG"; break;
}
struct peck *peck = eis_get_user_data(eis);
fprintf(stderr, "| | | EIS | %s |%*s🍨 %s",
prefix, peck_get_indent(peck), " ", message);
}
static void
peck_log_handler(struct logger *logger,
const char *prefix,
enum logger_priority priority,
const char *format, va_list args)
{
const char *msgtype;
switch(priority) {
case LOGGER_DEBUG: msgtype = "DBG"; break;
case LOGGER_INFO: msgtype = "INF"; break;
case LOGGER_WARN: msgtype = "WRN"; break;
case LOGGER_ERROR: msgtype = "ERR"; break;
default:
msgtype = "<invalid msgtype>";
break;
}
struct peck *peck = logger_get_user_data(logger);
fprintf(stderr, "| peck | | | %s |%*s",
msgtype, peck_get_indent(peck), " ");
vfprintf(stderr, format, args);
}
struct peck *
peck_new(void)
{
@ -75,7 +168,9 @@ peck_new(void)
int rc = socketpair(AF_UNIX, SOCK_STREAM|SOCK_NONBLOCK|SOCK_CLOEXEC, 0, sv);
munit_assert_int(rc, ==, 0);
struct ei *ei = ei_new(NULL);
struct ei *ei = ei_new(peck);
ei_set_user_data(ei, peck);
ei_log_set_handler(ei, peck_ei_log_handler);
ei_log_set_priority(ei, EI_LOG_PRIORITY_DEBUG);
ei_configure_name(ei, "eierpecken test context");
rc = ei_setup_backend_fd(ei, sv[0]);
@ -83,7 +178,8 @@ peck_new(void)
peck->ei = ei;
flag_set(peck->ei_behavior, PECK_EI_BEHAVIOR_AUTOCONNNECT);
struct eis *eis = eis_new(NULL);
struct eis *eis = eis_new(peck);
eis_log_set_handler(eis, peck_eis_log_handler);
eis_log_set_priority(eis, EIS_LOG_PRIORITY_DEBUG);
rc = eis_setup_backend_fd(eis);
munit_assert_int(rc, ==, 0);
@ -92,7 +188,8 @@ peck_new(void)
peck->eis = eis;
peck->eis_behavior = PECK_EIS_BEHAVIOR_NONE;
peck->logger = logger_new("peck", NULL);
peck->logger = logger_new("peck", peck);
logger_set_handler(peck->logger, peck_log_handler);
logger_set_priority(peck->logger, LOGGER_DEBUG);
return peck;
@ -191,10 +288,10 @@ peck_handle_eis_connect(struct peck *peck, struct eis_event *e)
struct eis_client *client = eis_event_get_client(e);
if (flag_is_set(peck->eis_behavior, PECK_EIS_BEHAVIOR_ACCEPT_CLIENT)) {
log_debug(peck, "EIS accepting client: %s\n", eis_client_get_name(client));
log_debug(peck, "EIS accepting client: '%s'\n", eis_client_get_name(client));
eis_client_connect(client);
} else {
log_debug(peck, "EIS disconnecting client: %s\n", eis_client_get_name(client));
log_debug(peck, "EIS disconnecting client: '%s'\n", eis_client_get_name(client));
eis_client_disconnect(client);
}
}
@ -238,12 +335,13 @@ peck_handle_eis_added(struct peck *peck, struct eis_event *e)
}
bool
peck_dispatch_eis(struct peck *peck)
_peck_dispatch_eis(struct peck *peck, int lineno)
{
struct eis *eis = peck->eis;
bool had_event = false;
log_debug(peck, "EIS Dispatch\n");
log_debug(peck, "EIS Dispatch, line %d\n", lineno);
peck_indent(peck);
while(true) {
eis_dispatch(eis);
@ -308,6 +406,8 @@ peck_dispatch_eis(struct peck *peck)
}
}
peck_dedent(peck);
return had_event;
}
@ -332,12 +432,13 @@ peck_check_ei_added(struct peck *peck, struct ei_event *e)
}
bool
peck_dispatch_ei(struct peck *peck)
_peck_dispatch_ei(struct peck *peck, int lineno)
{
struct ei *ei = peck->ei;
bool had_event = false;
log_debug(peck, "ei is dispatching\n");
log_debug(peck, "ei dispatch, line %d\n", lineno);
peck_indent(peck);
while (true) {
ei_dispatch(ei);
@ -397,6 +498,7 @@ peck_dispatch_ei(struct peck *peck)
}
}
peck_dedent(peck);
return had_event;
}
@ -405,14 +507,16 @@ _peck_dispatch_until_stable(struct peck *peck, int lineno)
{
bool eis, ei;
log_debug(peck, "dispatching until stable state at line %d >>>>>\n", lineno);
log_debug(peck, "dispatching until stable (line %d) {\n", lineno);
peck_indent(peck);
do {
eis = peck_dispatch_eis(peck);
ei = peck_dispatch_ei(peck);
eis = _peck_dispatch_eis(peck, lineno);
ei = _peck_dispatch_ei(peck, lineno);
} while (ei || eis);
log_debug(peck, "<<<<< stable at %d\n", lineno);
peck_dedent(peck);
log_debug(peck, "}\n", lineno);
}
void
@ -465,12 +569,13 @@ peck_assert_no_eis_events(struct eis *eis)
}
struct ei_event *
peck_ei_next_event(struct ei *ei, enum ei_event_type type)
_peck_ei_next_event(struct ei *ei, enum ei_event_type type, int lineno)
{
struct ei_event *event = ei_get_event(ei);
if (!event)
munit_errorf("Expected ei event type %s, got none\n",
peck_ei_event_type_name(type));
munit_errorf("Expected ei event type %s, got none, line %d\n",
peck_ei_event_type_name(type),
lineno);
munit_assert_string_equal(peck_ei_event_name(event),
peck_ei_event_type_name(type));
@ -478,12 +583,13 @@ peck_ei_next_event(struct ei *ei, enum ei_event_type type)
}
struct eis_event *
peck_eis_next_event(struct eis *eis, enum eis_event_type type)
_peck_eis_next_event(struct eis *eis, enum eis_event_type type, int lineno)
{
struct eis_event *event = eis_get_event(eis);
if (!event)
munit_errorf("Expected EIS event type %s, got none\n",
peck_eis_event_type_name(type));
munit_errorf("Expected EIS event type %s, got none, line %d\n",
peck_eis_event_type_name(type),
lineno);
munit_assert_string_equal(peck_eis_event_name(event),
peck_eis_event_type_name(type));

View file

@ -121,8 +121,10 @@ peck_get_eis(struct peck *peck);
* @return true if at least one event was processed according to the current
* behavior
*/
#define peck_dispatch_eis(_p) \
_peck_dispatch_eis(_p, __LINE__)
bool
peck_dispatch_eis(struct peck *peck);
_peck_dispatch_eis(struct peck *peck, int lineno);
/**
* Dispatch all events according to the currently defined behavior.
@ -134,8 +136,10 @@ peck_dispatch_eis(struct peck *peck);
* @return true if at least one behavior was processes according to the
* current behavior
*/
#define peck_dispatch_ei(_p) \
_peck_dispatch_ei(_p, __LINE__)
bool
peck_dispatch_ei(struct peck *peck);
_peck_dispatch_ei(struct peck *peck, int lineno);
struct peck *
peck_unref(struct peck *peck);
@ -172,11 +176,15 @@ peck_assert_no_eis_events(struct eis *eis);
void
peck_assert_no_ei_events(struct ei *ei);
#define peck_ei_next_event(_ei, _type) \
_peck_ei_next_event(_ei, _type, __LINE__)
struct ei_event *
peck_ei_next_event(struct ei *ei, enum ei_event_type type);
_peck_ei_next_event(struct ei *ei, enum ei_event_type type, int lineno);
#define peck_eis_next_event(_eis, _type) \
_peck_eis_next_event(_eis, _type, __LINE__)
struct eis_event *
peck_eis_next_event(struct eis *eis, enum eis_event_type type);
_peck_eis_next_event(struct eis *eis, enum eis_event_type type, int lineno);
const char *
peck_ei_event_name(struct ei_event *e);