From b0c50ff91135d7dfad314684c0d6b972c916bf4c Mon Sep 17 00:00:00 2001 From: Dan Shick Date: Thu, 20 Feb 2020 14:59:46 -0500 Subject: [PATCH] Add proper logging --- include/logger.h | 28 ++++++++++++ include/screencast_common.h | 5 +-- include/xdpw.h | 1 + meson.build | 1 + src/core/logger.c | 66 ++++++++++++++++++++++++++++ src/core/main.c | 28 ++++++++---- src/core/request.c | 4 +- src/core/session.c | 4 +- src/screencast/pipewire_screencast.c | 34 +++++++------- src/screencast/screencast.c | 47 ++++++++++---------- src/screencast/wlr_screencast.c | 26 +++++------ 11 files changed, 175 insertions(+), 69 deletions(-) create mode 100644 include/logger.h create mode 100644 src/core/logger.c diff --git a/include/logger.h b/include/logger.h new file mode 100644 index 0000000..241a778 --- /dev/null +++ b/include/logger.h @@ -0,0 +1,28 @@ +#ifndef LOGGER_H +#define LOGGER_H + +#include +#include +#include +#include +#include + +enum LOGLEVEL { + QUIET, + ERROR, + WARN, + INFO, + DEBUG, + TRACE +}; + +struct logger_properties{ + enum LOGLEVEL level; + FILE *__restrict__ dst; +}; + +void init_logger(FILE *__restrict__ dst, enum LOGLEVEL level); +enum LOGLEVEL get_loglevel(const char *level); +void logprint(enum LOGLEVEL level, char *msg, ...); + +#endif diff --git a/include/screencast_common.h b/include/screencast_common.h index 3d8956f..693bb71 100644 --- a/include/screencast_common.h +++ b/include/screencast_common.h @@ -6,10 +6,7 @@ #include #include #include - -// Disableable logger -//#define logger(...) printf(__VA_ARGS__) -#define logger(...) +#include "logger.h" struct damage { uint32_t x; diff --git a/include/xdpw.h b/include/xdpw.h index 0942207..d9c70e5 100644 --- a/include/xdpw.h +++ b/include/xdpw.h @@ -3,6 +3,7 @@ #include #include +#include "logger.h" struct xdpw_request { sd_bus_slot *slot; diff --git a/meson.build b/meson.build index e119149..8203209 100644 --- a/meson.build +++ b/meson.build @@ -36,6 +36,7 @@ executable( 'xdg-desktop-portal-wlr', files([ 'src/core/main.c', + 'src/core/logger.c', 'src/core/request.c', 'src/core/session.c', 'src/screenshot/screenshot.c', diff --git a/src/core/logger.c b/src/core/logger.c new file mode 100644 index 0000000..a169e2c --- /dev/null +++ b/src/core/logger.c @@ -0,0 +1,66 @@ +#include "logger.h" + +static int NUM_LEVELS = 6; + +static const char *loglevels[] = { + "QUIET", + "ERROR", + "WARN", + "INFO", + "DEBUG", + "TRACE" +}; + +static struct logger_properties logprops; + +void init_logger(FILE *__restrict__ dst, enum LOGLEVEL level){ + logprops.dst = dst; + logprops.level = level; +} + +enum LOGLEVEL get_loglevel(const char *level){ + int i; + for(i = 0; i < NUM_LEVELS; i++){ + if(!strcmp(level, loglevels[i])) return (enum LOGLEVEL) i; + } + fprintf(stderr, "Could not understand log level %s\n", level); + exit(EXIT_FAILURE); +} + +void logprint(enum LOGLEVEL level, char *msg, ...){ + + if(!logprops.dst){ + fprintf(stderr, "Logger has been called, but was not initialized\n"); + exit(EXIT_FAILURE); + } + + if(level > logprops.level || level == QUIET) return ; + + va_list args; + + char timestr[200]; + time_t t = time(NULL); + struct tm *tmp = localtime(&t); + + if (strftime(timestr, sizeof(timestr), "%Y/%m/%d %H:%M:%S", tmp) == 0) { + fprintf(stderr, "strftime returned 0"); + exit(EXIT_FAILURE); + } + + fprintf(logprops.dst, "%s", timestr); + + fprintf(logprops.dst, " "); + + fprintf(logprops.dst, "[%s]", loglevels[level]); + + fprintf(logprops.dst, " - "); + + va_start(args, msg); + vfprintf(logprops.dst, msg, args); + va_end(args); + + + fprintf(logprops.dst, "\n"); + fflush(logprops.dst); + +} \ No newline at end of file diff --git a/src/core/main.c b/src/core/main.c index 0592662..117a24c 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -10,10 +10,12 @@ int xdpw_usage(FILE* stream, int rc) static const char* usage = "Usage: xdg-desktop-portal-wlr [options]\n" "\n" -" -o, --output= Select output to capture.\n" -" -p,--pixelformat=BGRx|RGBx Force a pixelformat in pipewire\n" -" metadata (performs no conversion).\n" -" -h,--help Get help (this text).\n" +" -l, --loglevel= Select log level (default is ERROR).\n" +" QUIET, ERROR, WARN, INFO, DEBUG, TRACE\n" +" -o, --output= Select output to capture.\n" +" -p,--pixelformat=BGRx|RGBx Force a pixelformat in pipewire\n" +" metadata (performs no conversion).\n" +" -h,--help Get help (this text).\n" "\n"; fprintf(stream, "%s", usage); @@ -25,9 +27,11 @@ int main(int argc, char *argv[]) { const char* output_name = NULL; const char* forced_pixelformat = NULL; + enum LOGLEVEL loglevel = ERROR; - static const char* shortopts = "o:p:h"; + static const char* shortopts = "l:o:p:h"; static const struct option longopts[] = { + { "loglevel", required_argument, NULL, 'l' }, { "output", required_argument, NULL, 'o' }, { "pixelformat", required_argument, NULL, 'p' }, { "help", no_argument, NULL, 'h' }, @@ -40,6 +44,9 @@ int main(int argc, char *argv[]) { break; switch (c) { + case 'l': + loglevel = get_loglevel(optarg); + break; case 'o': output_name = optarg; break; @@ -53,12 +60,14 @@ int main(int argc, char *argv[]) { } } + init_logger(stderr, loglevel); + int ret = 0; sd_bus *bus = NULL; ret = sd_bus_open_user(&bus); if (ret < 0) { - fprintf(stderr, "Failed to connect to user bus: %s\n", strerror(-ret)); + logprint(ERROR, "dbus: failed to connect to user bus: %s", strerror(-ret)); goto error; } @@ -67,14 +76,15 @@ int main(int argc, char *argv[]) { ret = sd_bus_request_name(bus, service_name, 0); if (ret < 0) { - fprintf(stderr, "Failed to acquire service name: %s\n", strerror(-ret)); + logprint(ERROR, "dbus: failed to acquire service name: %s", strerror(-ret)); goto error; } while (1) { ret = sd_bus_process(bus, NULL); if (ret < 0) { - fprintf(stderr, "sd_bus_process failed: %s\n", strerror(-ret)); + logprint(ERROR, "dbus: sd_bus_process failed: %s", strerror(-ret)); + goto error; } else if (ret > 0) { // We processed a request, try to process another one, right-away continue; @@ -82,7 +92,7 @@ int main(int argc, char *argv[]) { ret = sd_bus_wait(bus, (uint64_t)-1); if (ret < 0) { - fprintf(stderr, "sd_bus_wait failed: %s\n", strerror(-ret)); + logprint(ERROR, "dbus: sd_bus_wait failed: %s", strerror(-ret)); goto error; } } diff --git a/src/core/request.c b/src/core/request.c index 719a623..ba7edea 100644 --- a/src/core/request.c +++ b/src/core/request.c @@ -12,7 +12,7 @@ static int method_close(sd_bus_message *msg, void *data, int ret = 0; // struct xdpw_request *req = data; // TODO - printf("Request.Close\n"); + logprint(INFO, "dbus: request closed"); sd_bus_message *reply = NULL; ret = sd_bus_message_new_method_return(msg, &reply); @@ -42,7 +42,7 @@ struct xdpw_request *request_create(sd_bus *bus, const char *object_path) { if (sd_bus_add_object_vtable(bus, &req->slot, object_path, interface_name, request_vtable, NULL) < 0) { free(req); - fprintf(stderr, "sd_bus_add_object_vtable failed: %s\n", + logprint(ERROR, "dbus: sd_bus_add_object_vtable failed: %s", strerror(-errno)); return NULL; } diff --git a/src/core/session.c b/src/core/session.c index 8a9b005..6c2b4c4 100644 --- a/src/core/session.c +++ b/src/core/session.c @@ -12,7 +12,7 @@ static int method_close(sd_bus_message *msg, void *data, int ret = 0; // struct xdpw_session *session = data; // TODO - printf("Session.Close\n"); + logprint(INFO, "dbus: session closed"); sd_bus_message *reply = NULL; ret = sd_bus_message_new_method_return(msg, &reply); @@ -42,7 +42,7 @@ struct xdpw_session *session_create(sd_bus *bus, const char *object_path) { if (sd_bus_add_object_vtable(bus, &req->slot, object_path, interface_name, session_vtable, NULL) < 0) { free(req); - fprintf(stderr, "sd_bus_add_object_vtable failed: %s\n", + logprint(ERROR, "dbus: sd_bus_add_object_vtable failed: %s", strerror(-errno)); return NULL; } diff --git a/src/screencast/pipewire_screencast.c b/src/screencast/pipewire_screencast.c index 3d29280..13c14bd 100644 --- a/src/screencast/pipewire_screencast.c +++ b/src/screencast/pipewire_screencast.c @@ -36,10 +36,11 @@ static void pwr_on_event(void *data, uint64_t expirations) { return; } - logger("pw event fired\n"); + logprint(TRACE, "********************"); + logprint(TRACE, "pipewire: event fired"); if ((pw_buf = pw_stream_dequeue_buffer(ctx->stream)) == NULL) { - printf("out of buffers\n"); + logprint(WARN, "pipewire: out of buffers"); return; } @@ -67,14 +68,13 @@ static void pwr_on_event(void *data, uint64_t expirations) { writeFrameData(d[0].data, ctx->simple_frame.data, ctx->simple_frame.height, ctx->simple_frame.stride, ctx->simple_frame.y_invert); - logger("************** \n"); - logger("pointer: %p\n", d[0].data); - logger("size: %d\n", d[0].maxsize); - logger("stride: %d\n", d[0].chunk->stride); - logger("width: %d\n", ctx->simple_frame.width); - logger("height: %d\n", ctx->simple_frame.height); - logger("y_invert: %d\n", ctx->simple_frame.y_invert); - logger("************** \n"); + logprint(TRACE, "pipewire: pointer %p", d[0].data); + logprint(TRACE, "pipewire: size %d", d[0].maxsize); + logprint(TRACE, "pipewire: stride %d", d[0].chunk->stride); + logprint(TRACE, "pipewire: width %d", ctx->simple_frame.width); + logprint(TRACE, "pipewire: height %d", ctx->simple_frame.height); + logprint(TRACE, "pipewire: y_invert %d", ctx->simple_frame.y_invert); + logprint(TRACE, "********************"); pw_stream_queue_buffer(ctx->stream, pw_buf); @@ -88,8 +88,8 @@ static void pwr_handle_stream_state_changed(void *data, struct screencast_context *ctx = data; ctx->node_id = pw_stream_get_node_id(ctx->stream); - printf("stream state: \"%s\"\n", pw_stream_state_as_string(state)); - printf("node id: %d\n", ctx->node_id); + logprint(INFO, "pipewire: stream state changed to \"%s\"", pw_stream_state_as_string(state)); + logprint(INFO, "pipewire: node id is %d", ctx->node_id); switch (state) { case PW_STREAM_STATE_PAUSED: @@ -149,7 +149,9 @@ static void pwr_handle_state_changed(void *data, enum pw_remote_state old, switch (state) { case PW_REMOTE_STATE_ERROR: - printf("remote error: %s\n", error); + logprint(INFO, "pipewire: remote state changed to \"%s\"", + pw_remote_state_as_string(state)); + logprint(ERROR, "pipewire: remote error: %s", error); pw_main_loop_quit(ctx->loop); break; @@ -158,7 +160,8 @@ static void pwr_handle_state_changed(void *data, enum pw_remote_state old, uint8_t buffer[1024]; struct spa_pod_builder b = SPA_POD_BUILDER_INIT(buffer, sizeof(buffer)); - logger("remote state: \"%s\"\n", pw_remote_state_as_string(state)); + logprint(INFO, "pipewire: remote state changed to \"%s\"", + pw_remote_state_as_string(state)); ctx->stream = pw_stream_new( remote, "wlr_screeencopy", @@ -190,7 +193,8 @@ static void pwr_handle_state_changed(void *data, enum pw_remote_state old, break; } default: - logger("remote state: \"%s\"\n", pw_remote_state_as_string(state)); + logprint(INFO, "pipewire: remote state changed to \"%s\"", + pw_remote_state_as_string(state)); break; } } diff --git a/src/screencast/screencast.c b/src/screencast/screencast.c index 0aaef55..ac1acc9 100644 --- a/src/screencast/screencast.c +++ b/src/screencast/screencast.c @@ -9,7 +9,7 @@ int setup_outputs(struct screencast_context *ctx) { struct wayland_output *output, *tmp_o; wl_list_for_each_reverse_safe(output, tmp_o, &ctx->output_list, link) { - printf("Capturable output: %s Model: %s: ID: %i Name: %s\n", output->make, + logprint(INFO, "wlroots: capturable output: %s model: %s: id: %i name: %s", output->make, output->model, output->id, output->name); } @@ -17,23 +17,22 @@ int setup_outputs(struct screencast_context *ctx) { if (ctx->output_name) { out = wlr_output_find_by_name(&ctx->output_list, ctx->output_name); if (!out) { - printf("No such output\n"); + logprint(ERROR, "wlroots: no such output"); exit(EXIT_FAILURE); } } else { out = wlr_output_first(&ctx->output_list); if (!out) { - printf("No output found\n"); + logprint(ERROR, "wlroots: no output found"); exit(EXIT_FAILURE); } } - printf("here %s\n", out->name); ctx->target_output = out; ctx->framerate = out->framerate; ctx->with_cursor = true; - printf("wl_display fd: %d\n", wl_display_get_fd(ctx->display)); + logprint(INFO, "wlroots: wl_display fd: %d", wl_display_get_fd(ctx->display)); return 0; @@ -62,7 +61,7 @@ static int method_screencast_create_session(sd_bus_message *msg, void *data, sd_bus_error *ret_error) { int ret = 0; - printf("=== CREATE SESSION\n"); + logprint(INFO, "dbus: create session method invoked"); char *request_handle, *session_handle, *app_id; ret = sd_bus_message_read(msg, "oos", &request_handle, &session_handle, &app_id); @@ -75,9 +74,9 @@ static int method_screencast_create_session(sd_bus_message *msg, void *data, return ret; } - printf("request_handle: %s\n", request_handle); - printf("session_handle: %s\n", session_handle); - printf("app_id: %s\n", app_id); + logprint(INFO, "dbus: request_handle: %s", request_handle); + logprint(INFO, "dbus: session_handle: %s", session_handle); + logprint(INFO, "dbus: app_id: %s", app_id); char* key; int innerRet = 0; @@ -90,9 +89,9 @@ static int method_screencast_create_session(sd_bus_message *msg, void *data, if(strcmp(key, "session_handle_token") == 0) { char* token; sd_bus_message_read(msg, "v", "s", &token); - printf("Option token = %s\n", token); + logprint(INFO, "dbus: option token: %s", token); } else { - printf("Unknown option %s\n", key); + logprint(WARN, "dbus: unknown option: %s", key); sd_bus_message_skip(msg, "v"); } @@ -149,7 +148,7 @@ static int method_screencast_select_sources(sd_bus_message *msg, void *data, sd_ int ret = 0; - printf("=== SELECT SOURCES\n"); + logprint(INFO, "dbus: select sources method invoked"); setup_outputs(ctx); @@ -163,9 +162,9 @@ static int method_screencast_select_sources(sd_bus_message *msg, void *data, sd_ return ret; } - printf("request_handle: %s\n", request_handle); - printf("session_handle: %s\n", session_handle); - printf("app_id: %s\n", app_id); + logprint(INFO, "dbus: request_handle: %s", request_handle); + logprint(INFO, "dbus: session_handle: %s", session_handle); + logprint(INFO, "dbus: app_id: %s", app_id); char* key; int innerRet = 0; @@ -178,13 +177,13 @@ static int method_screencast_select_sources(sd_bus_message *msg, void *data, sd_ if(strcmp(key, "multiple") == 0) { bool multiple; sd_bus_message_read(msg, "v", "b", &multiple); - printf("Option multiple, val %x\n", multiple); + logprint(INFO, "dbus: option multiple: %x", multiple); } else if(strcmp(key, "types") == 0) { uint32_t mask; sd_bus_message_read(msg, "v", "u", &mask); - printf("Option types, mask %x\n", mask); + logprint(INFO, "dbus: option types: %x", mask); } else { - printf("Unknown option %s\n", key); + logprint(WARN, "dbus: unknown option %s", key); sd_bus_message_skip(msg, "v"); } @@ -226,7 +225,7 @@ static int method_screencast_start(sd_bus_message *msg, void *data, sd_bus_error int ret = 0; - printf("=== START\n"); + logprint(INFO, "dbus: start method invoked"); pthread_t screencast_thread; pthread_create(&screencast_thread, NULL, start_screencast, ctx); @@ -241,10 +240,10 @@ static int method_screencast_start(sd_bus_message *msg, void *data, sd_bus_error return ret; } - printf("request_handle: %s\n", request_handle); - printf("session_handle: %s\n", session_handle); - printf("app_id: %s\n", app_id); - printf("parent_window: %s\n", parent_window); + logprint(INFO, "dbus: request_handle: %s", request_handle); + logprint(INFO, "dbus: session_handle: %s", session_handle); + logprint(INFO, "dbus: app_id: %s", app_id); + logprint(INFO, "dbus: parent_window: %s", parent_window); char* key; int innerRet = 0; @@ -254,7 +253,7 @@ static int method_screencast_start(sd_bus_message *msg, void *data, sd_bus_error return innerRet; } - printf("Unknown option %s\n", key); + logprint(WARN, "dbus: unknown option: %s", key); sd_bus_message_skip(msg, "v"); innerRet = sd_bus_message_exit_container(msg); diff --git a/src/screencast/wlr_screencast.c b/src/screencast/wlr_screencast.c index c3f022a..2e05097 100644 --- a/src/screencast/wlr_screencast.c +++ b/src/screencast/wlr_screencast.c @@ -5,7 +5,7 @@ void wlr_frame_free(struct screencast_context *ctx) { zwlr_screencopy_frame_v1_destroy(ctx->wlr_frame); munmap(ctx->simple_frame.data, ctx->simple_frame.size); wl_buffer_destroy(ctx->simple_frame.buffer); - logger("wlr frame destroyed\n"); + logprint(TRACE, "wlroots: frame destroyed"); pthread_mutex_unlock(&ctx->lock); } @@ -19,7 +19,7 @@ static struct wl_buffer *create_shm_buffer(struct screencast_context *ctx, const char shm_name[] = "/wlroots-screencopy"; int fd = shm_open(shm_name, O_RDWR | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR); if (fd < 0) { - fprintf(stderr, "shm_open failed\n"); + logprint(ERROR, "wlroots: shm_open failed"); return NULL; } shm_unlink(shm_name); @@ -30,13 +30,13 @@ static struct wl_buffer *create_shm_buffer(struct screencast_context *ctx, } if (ret < 0) { close(fd); - fprintf(stderr, "ftruncate failed\n"); + logprint(ERROR, "wlroots: ftruncate failed"); return NULL; } void *data = mmap(NULL, size, PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0); if (data == MAP_FAILED) { - fprintf(stderr, "mmap failed: %m\n"); + logprint(ERROR, "wlroots: mmap failed: %m"); close(fd); return NULL; } @@ -58,7 +58,7 @@ static void wlr_frame_buffer(void *data, struct zwlr_screencopy_frame_v1 *frame, pthread_mutex_lock(&ctx->lock); - logger("wlr buffer event handler\n"); + logprint(TRACE, "wlroots: buffer event handler"); ctx->wlr_frame = frame; ctx->simple_frame.width = width; ctx->simple_frame.height = height; @@ -68,7 +68,7 @@ static void wlr_frame_buffer(void *data, struct zwlr_screencopy_frame_v1 *frame, ctx->simple_frame.buffer = create_shm_buffer(ctx, format, width, height, stride, &ctx->simple_frame.data); if (ctx->simple_frame.buffer == NULL) { - fprintf(stderr, "failed to create buffer\n"); + logprint(ERROR, "wlroots: failed to create buffer"); exit(EXIT_FAILURE); } @@ -83,7 +83,7 @@ static void wlr_frame_flags(void *data, struct zwlr_screencopy_frame_v1 *frame, pthread_mutex_lock(&ctx->lock); - logger("wlr flags event handler\n"); + logprint(TRACE, "wlroots: flags event handler"); ctx->simple_frame.y_invert = flags & ZWLR_SCREENCOPY_FRAME_V1_FLAGS_Y_INVERT; pthread_mutex_unlock(&ctx->lock); @@ -96,7 +96,7 @@ static void wlr_frame_ready(void *data, struct zwlr_screencopy_frame_v1 *frame, pthread_mutex_lock(&ctx->lock); - logger("wlr ready event handler\n"); + logprint(TRACE, "wlroots: ready event handler"); ctx->simple_frame.tv_sec = ((((uint64_t)tv_sec_hi) << 32) | tv_sec_lo); ctx->simple_frame.tv_nsec = tv_nsec; @@ -112,7 +112,7 @@ static void wlr_frame_failed(void *data, struct zwlr_screencopy_frame_v1 *frame) { struct screencast_context *ctx = data; - logger("wlr failed event handler\n"); + logprint(TRACE, "wlroots: failed event handler"); wlr_frame_free(ctx); ctx->err = true; @@ -143,7 +143,7 @@ void wlr_register_cb(struct screencast_context *ctx) { zwlr_screencopy_frame_v1_add_listener(ctx->frame_callback, &wlr_frame_listener, ctx); - logger("wlr callbacks registered\n"); + logprint(TRACE, "wlroots: callbacks registered"); } static void wlr_output_handle_geometry(void *data, struct wl_output *wl_output, @@ -296,7 +296,7 @@ int wlr_screencopy_init(struct screencast_context *ctx) { // connect to wayland display WAYLAND_DISPLAY or 'wayland-0' if not set ctx->display = wl_display_connect(NULL); if (!ctx->display) { - printf("Failed to connect to display!\n"); + logprint(ERROR, "Failed to connect to display!"); return -1; } @@ -317,13 +317,13 @@ int wlr_screencopy_init(struct screencast_context *ctx) { // make sure our wlroots supports screencopy protocol if (!ctx->shm) { - printf("Compositor doesn't support %s!\n", "wl_shm"); + logprint(ERROR, "Compositor doesn't support %s!", "wl_shm"); return -1; } // make sure our wlroots supports screencopy protocol if (!ctx->screencopy_manager) { - printf("Compositor doesn't support %s!\n", + logprint(ERROR, "Compositor doesn't support %s!", zwlr_screencopy_manager_v1_interface.name); return -1; }