hippoz/jitterbug
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

better logging

Browse source
This commit is contained in:
hippoz 2023-01-16 02:20:53 +02:00
parent f0cef536ff
commit 63fd9dd698
Signed by: hippoz
GPG key ID: 56C4E02A85F2FBED
6 changed files with 73 additions and 37 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

8
Makefile
View file

@ -1,5 +1,11 @@
CC?=gcc CC?=gcc
CFLAGS+=-Wall -Wextra -Wshadow -pedantic -std=c99 -ggdb -fsanitize=address
CFLAGS_DEV=-DJB_PRESET_DEBUG -ggdb -fsanitize=address -Og
CFLAGS_RELEASE=-O2 -ggdb
CFLAGS+=-pipe -Wall -Wextra -Wshadow -pedantic -std=c99
CFLAGS+=$(CFLAGS_RELEASE)
jitterbug: util.c wire.c match.c server.c main.c jitterbug: util.c wire.c match.c server.c main.c
$(CC) $(CFLAGS) -o $@ $^ $(CC) $(CFLAGS) -o $@ $^

10
config.h Normal file
View file

@ -0,0 +1,10 @@
#ifndef __JITTERBUG_CONFIG_H
#define __JITTERBUG_CONFIG_H
#ifdef JB_PRESET_DEBUG
#define JB_ENABLE_TRY_TRACE
#define JB_ENABLE_VERBOSE
#define JB_ENABLE_WARN
#endif
#endif // __JITTERBUG_CONFIG_H

22
log.h Normal file
View file

@ -0,0 +1,22 @@
#ifndef __JITTERBUG_LOG_H
#define __JITTERBUG_LOG_H
#include "config.h"
#ifdef JB_ENABLE_VERBOSE
#define VERBOSE printf
#else
#define VERBOSE(...)
#endif
#ifdef JB_ENABLE_WARN
#define WARN printf
#else
#define WARN(...)
#endif
#define ERROR(...) fprintf(stderr, __VA_ARGS__)
#define STUB(M_where, M_kind) WARN("stub: %s: %s\n", (M_where), (M_kind))
#endif // __JITTERBUG_LOG_H

41
server.c
View file

@ -13,6 +13,7 @@
#include "server.h" #include "server.h"
#include "wire.h" #include "wire.h"
#include "util.h" #include "util.h"
#include "log.h"
// https://en.wikipedia.org/wiki/Fowler-Noll-Vo_hash_function#FNV-1a_hash // https://en.wikipedia.org/wiki/Fowler-Noll-Vo_hash_function#FNV-1a_hash
@ -272,7 +273,7 @@ void bus_client_remove(bus_t *s, int i)
void bus_client_error(bus_t *s, int i, const char *msg) void bus_client_error(bus_t *s, int i, const char *msg)
{ {
printf("bus_client_error: %s\n", msg); WARN("removing client %d due to error: %s\n", i, msg);
send(s->clients[i].fd, msg, strlen(msg), 0); send(s->clients[i].fd, msg, strlen(msg), 0);
bus_client_remove(s, i); bus_client_remove(s, i);
} }
@ -394,7 +395,7 @@ int bus_unicast_message(bus_t *s, wire_message_t *msg, wire_context_t *ctx, char
if (send(s->fds[i].fd, reply_ctx->data, reply_ctx->byte_cursor, 0) != reply_ctx->byte_cursor) { \ if (send(s->fds[i].fd, reply_ctx->data, reply_ctx->byte_cursor, 0) != reply_ctx->byte_cursor) { \
return -1; \ return -1; \
} \ } \
printf("reply_end: send: sent %d bytes!\n", reply_ctx->byte_cursor); \ VERBOSE("sent response of %d byte(s)\n", reply_ctx->byte_cursor); \
} /* if (!(msg.flags & DBUS_FLAG_NO_REPLY_EXPECTED)) */ } /* if (!(msg.flags & DBUS_FLAG_NO_REPLY_EXPECTED)) */
#define _reply_error(message) \ #define _reply_error(message) \
@ -425,7 +426,7 @@ int handle_hello(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire
TRYPTR(wire_set_string(&signal_reply_ctx, "")); TRYPTR(wire_set_string(&signal_reply_ctx, ""));
} _signal_end(); } _signal_end();
printf("assigned unique name '%s' to connection %d\n", s->names[unique_name_index].name, i); VERBOSE("assigned unique name '%s' to connection %d\n", s->names[unique_name_index].name, i);
return 0; return 0;
} }
@ -461,7 +462,7 @@ int handle_request_name(bus_t *s, int i, wire_message_t *msg, wire_context_t *ct
TRYPTR(wire_set_string(&signal_reply_ctx, s->names[s->clients[i].unique_name_index].name)); TRYPTR(wire_set_string(&signal_reply_ctx, s->names[s->clients[i].unique_name_index].name));
} _signal_end(); } _signal_end();
printf("client '%s' (index=%d) now owns name '%s'\n", s->names[s->clients[i].unique_name_index].name, i, name_str); VERBOSE("client '%s' (index=%d) now owns name '%s'\n", s->names[s->clients[i].unique_name_index].name, i, name_str);
} }
return 0; return 0;
} }
@ -521,8 +522,7 @@ int handle_list_names(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx,
int handle_list_activatable_names(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) { int handle_list_activatable_names(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) {
(void)ctx; (void)ctx;
// TODO: stub (always returns empty array) STUB("handle_list_activatable_names", "always returns empty array");
printf("FIXME: STUB: ListActivatableNames\n");
_reply_begin("as") { _reply_begin("as") {
TRYPTR(wire_set_u32(reply_ctx, 0)); TRYPTR(wire_set_u32(reply_ctx, 0));
@ -533,14 +533,12 @@ int handle_list_activatable_names(bus_t *s, int i, wire_message_t *msg, wire_con
} }
int handle_start_service_by_name(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) { int handle_start_service_by_name(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) {
// TODO: stub (does nothing and always returns success)
char *name = TRYPTR(wire_get_name_string(ctx)); char *name = TRYPTR(wire_get_name_string(ctx));
/* unused flags value */ /* unused flags value */
TRYPTR(wire_get_u32(ctx)); TRYPTR(wire_get_u32(ctx));
printf("FIXME: STUB: StartServiceByName: %s\n", name); STUB("handle_start_service_by_name", "does nothing and returns success");
_reply_begin("u") { _reply_begin("u") {
TRYPTR(wire_set_u32(reply_ctx, 1)); TRYPTR(wire_set_u32(reply_ctx, 1));
@ -551,7 +549,7 @@ int handle_start_service_by_name(bus_t *s, int i, wire_message_t *msg, wire_cont
int handle_add_match(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) { int handle_add_match(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) {
char *match = TRYPTR(wire_get_string_check(ctx, 1, MATCH_RULE_MAX)); char *match = TRYPTR(wire_get_string_check(ctx, 1, MATCH_RULE_MAX));
printf("client index %d adding match rule: '%s'\n", i, match); VERBOSE("client index %d adding match rule: '%s'\n", i, match);
TRYST(bus_client_match_add(s, i, match)); TRYST(bus_client_match_add(s, i, match));
@ -560,11 +558,9 @@ int handle_add_match(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx,
} }
int handle_remove_match(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) { int handle_remove_match(bus_t *s, int i, wire_message_t *msg, wire_context_t *ctx, wire_context_t *reply_ctx) {
// TODO: stub (does nothing and always returns success)
char *match = TRYPTR(wire_get_string_check(ctx, 1, MATCH_RULE_MAX)); char *match = TRYPTR(wire_get_string_check(ctx, 1, MATCH_RULE_MAX));
printf("FIXME: STUB: RemoveMatch: %s\n", match); STUB("handle_remove_match", "does nothing and returns success");
_reply_begin("") {} _reply_end() _reply_begin("") {} _reply_end()
return 0; return 0;
@ -575,8 +571,7 @@ int handle_get_connection_stats(bus_t *s, int i, wire_message_t *msg, wire_conte
TRYPTR(wire_get_name_string(ctx)); TRYPTR(wire_get_name_string(ctx));
// TODO: stub (always returns empty array) STUB("handle_get_connection_stats", "always returns empty array");
printf("FIXME: STUB: GetConnectionStats\n");
_reply_begin("as") { _reply_begin("as") {
TRYPTR(wire_set_u32(reply_ctx, 0)); TRYPTR(wire_set_u32(reply_ctx, 0));
@ -688,7 +683,7 @@ int bus_client_process_message(bus_t *s, int i, wire_context_t *ctx)
wire_message_t msg = {0}; wire_message_t msg = {0};
if (wire_parse_message(ctx, &msg) < 0) { if (wire_parse_message(ctx, &msg) < 0) {
printf("parsing failed\n"); WARN("parsing failed\n");
return -1; return -1;
} }
@ -717,7 +712,7 @@ int bus_client_process_message(bus_t *s, int i, wire_context_t *ctx)
goto end_nonfatal; goto end_nonfatal;
} }
} }
printf("FIXME: daemon method '%s' is not implemented or invalid\n", member_field->t.str); WARN("FIXME: daemon method '%s' is not implemented or invalid\n", member_field->t.str);
_process_message_reply_error("org.freedesktop.DBus.Error.UnknownMethod"); _process_message_reply_error("org.freedesktop.DBus.Error.UnknownMethod");
goto end_nonfatal; goto end_nonfatal;
} }
@ -754,7 +749,7 @@ end_nonfatal:
// body and print an error message. In the future, we may want to have // body and print an error message. In the future, we may want to have
// separate debug builds, and maybe exit the program if we are in a // separate debug builds, and maybe exit the program if we are in a
// debug build and we encounter something like this. // debug build and we encounter something like this.
fprintf(stderr, "notice: parsing code did not consume the entire message (expected: %d, actual: %d)\n", body_end, ctx->byte_cursor); WARN("parsing code did not consume the entire message (expected: %d, actual: %d)\n", body_end, ctx->byte_cursor);
ctx->byte_cursor = body_end; ctx->byte_cursor = body_end;
} }
@ -783,7 +778,7 @@ int bus_client_drain_messages(bus_t *s, int ci, uint8_t *data, uint32_t data_len
TRYST(bus_client_process_message(s, ci, &ctx)); TRYST(bus_client_process_message(s, ci, &ctx));
} }
printf("processed %d messages - cursor:%d; data_len:%ld\n", i + 1, ctx.byte_cursor, ctx.data_len); VERBOSE("processed %d messages - cursor:%d; data_len:%ld\n", i + 1, ctx.byte_cursor, ctx.data_len);
return 0; return 0;
} }
@ -812,12 +807,12 @@ int bus_turn(bus_t *s)
for (int i = 0; i < s->fd_num; i++) { for (int i = 0; i < s->fd_num; i++) {
int fd = s->fds[i].fd; int fd = s->fds[i].fd;
if (s->fds[i].revents & POLLNVAL) { if (s->fds[i].revents & POLLNVAL) {
fprintf(stderr, "bus_turn: error: got POLLNVAL for fds[%d]. This is considered a bug in the server implementation.\n", i); ERROR("bus_turn: error: got POLLNVAL for fds[%d]. This is considered a bug in the server implementation.\n", i);
return -1; return -1;
} }
if (s->fds[i].revents & POLLERR) { if (s->fds[i].revents & POLLERR) {
if (fd == s->sock_fd) { if (fd == s->sock_fd) {
fprintf(stderr, "bus_turn: error: got POLLERR for sock_fd\n"); ERROR("bus_turn: error: got POLLERR for sock_fd\n");
return -1; return -1;
} }
bus_client_remove(s, i); bus_client_remove(s, i);
@ -825,7 +820,7 @@ int bus_turn(bus_t *s)
} }
if (s->fds[i].revents & POLLHUP) { if (s->fds[i].revents & POLLHUP) {
if (fd == s->sock_fd) { if (fd == s->sock_fd) {
fprintf(stderr, "bus_turn: error: got POLLHUP for sock_fd\n"); ERROR("bus_turn: error: got POLLHUP for sock_fd\n");
return -1; return -1;
} }
bus_client_remove(s, i); bus_client_remove(s, i);
@ -855,7 +850,7 @@ int bus_turn(bus_t *s)
continue; continue;
} }
printf("\nrecv: got %zd bytes\n", bytes); VERBOSE("\nrecv: got %zd bytes\n", bytes);
bus_client_t *c = &s->clients[i]; bus_client_t *c = &s->clients[i];
switch (c->state) { switch (c->state) {

11
try.h
View file

@ -1,6 +1,13 @@
#ifndef __JITTERBUG_TRY_H
#define __JITTERBUG_TRY_H
#ifdef JB_ENABLE_TRY_TRACE
#define __TRY_TRACE() do { \ #define __TRY_TRACE() do { \
printf("trace: %s:%d\n", __FILE__, __LINE__); \ printf("trace: %s:%d\n", __FILE__, __LINE__); \
} while(0) \ } while(0)
#else
#define __TRY_TRACE()
#endif // JB_ENABLE_TRY_TRACE
// NOTE: The macro(s) below make use of a GCC extension called "Statement Exprs", which is nonstandard. // NOTE: The macro(s) below make use of a GCC extension called "Statement Exprs", which is nonstandard.
@ -11,3 +18,5 @@
#define TRYST_NIL(M_expr) __extension__({ int _result = (int)(M_expr); if (_result < 0) { __TRY_TRACE(); return (NULL); } _result; }) #define TRYST_NIL(M_expr) __extension__({ int _result = (int)(M_expr); if (_result < 0) { __TRY_TRACE(); return (NULL); } _result; })
#define TRYST(M_expr) __extension__({ int _result = (int)(M_expr); if (_result < 0) { __TRY_TRACE(); return (-1); } _result; }) #define TRYST(M_expr) __extension__({ int _result = (int)(M_expr); if (_result < 0) { __TRY_TRACE(); return (-1); } _result; })
#endif // __JITTERBUG_TRY_H

18
wire.c
View file

@ -2,13 +2,7 @@
#include <stdio.h> #include <stdio.h>
#include "try.h" #include "try.h"
#include "wire.h" #include "wire.h"
#include "log.h"
#define WIRE_ENABLE_VERBOSE 1
#if WIRE_ENABLE_VERBOSE
#define WIRE_VERBOSE printf
#else
#define WIRE_VERBOSE(...)
#endif
bool wire_align(wire_context_t *c, uint32_t alignment) bool wire_align(wire_context_t *c, uint32_t alignment)
{ {
@ -125,7 +119,7 @@ int wire_parse_message(wire_context_t *c, wire_message_t *msg)
size_t header_fields_end = c->byte_cursor + msg->header_fields_length; size_t header_fields_end = c->byte_cursor + msg->header_fields_length;
WIRE_VERBOSE("start parse message: type=%d, no_reply_expected=%d\n", msg->type, msg->flags & DBUS_FLAG_NO_REPLY_EXPECTED); VERBOSE("start parse message: type=%d, no_reply_expected=%d\n", msg->type, msg->flags & DBUS_FLAG_NO_REPLY_EXPECTED);
while (c->byte_cursor < header_fields_end) { while (c->byte_cursor < header_fields_end) {
uint8_t field_code = *(uint8_t*)TRYPTR(wire_get_u8(c)); uint8_t field_code = *(uint8_t*)TRYPTR(wire_get_u8(c));
@ -137,17 +131,17 @@ int wire_parse_message(wire_context_t *c, wire_message_t *msg)
case DBUS_HEADER_FIELD_MEMBER: /* through */ case DBUS_HEADER_FIELD_MEMBER: /* through */
case DBUS_HEADER_FIELD_DESTINATION: { case DBUS_HEADER_FIELD_DESTINATION: {
char *str = TRYPTR(wire_get_string(c)); char *str = TRYPTR(wire_get_string(c));
WIRE_VERBOSE("field: %s\n", str); VERBOSE("field: %s\n", str);
msg->fields[field_code].t.str = str; msg->fields[field_code].t.str = str;
} break; } break;
case DBUS_HEADER_FIELD_SIGNATURE: { case DBUS_HEADER_FIELD_SIGNATURE: {
char *str = TRYPTR(wire_get_signature(c)); char *str = TRYPTR(wire_get_signature(c));
WIRE_VERBOSE("field: %s\n", str); VERBOSE("field: %s\n", str);
msg->fields[field_code].t.str = str; msg->fields[field_code].t.str = str;
} break; } break;
case DBUS_HEADER_FIELD_REPLY_SERIAL: { case DBUS_HEADER_FIELD_REPLY_SERIAL: {
uint32_t u = *(uint32_t*)TRYPTR(wire_get_u32(c)); uint32_t u = *(uint32_t*)TRYPTR(wire_get_u32(c));
WIRE_VERBOSE("field: %d\n", u); VERBOSE("field: %d\n", u);
msg->fields[field_code].t.u32 = u; msg->fields[field_code].t.u32 = u;
} break; } break;
default: { default: {
@ -166,7 +160,7 @@ int wire_parse_message(wire_context_t *c, wire_message_t *msg)
} }
} }
WIRE_VERBOSE("end parse message\n"); VERBOSE("end parse message\n");
/* header ends at 8 byte boundry */ /* header ends at 8 byte boundry */
TRYPTR(wire_align(c, 8)); TRYPTR(wire_align(c, 8));