Add proper logging

include/logger.h

@@ -0,0 +1,28 @@
+#ifndef LOGGER_H
+#define LOGGER_H
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdarg.h>
+#include <string.h>
+#include <time.h>
+
+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

include/screencast_common.h

@@ -6,10 +6,7 @@
 #include <spa/param/video/format-utils.h>
 #include <libdrm/drm_fourcc.h>
 #include <wayland-client-protocol.h>
-
-// Disableable logger
-//#define logger(...) printf(__VA_ARGS__)
-#define logger(...)
+#include "logger.h"
 
 struct damage {
 	uint32_t x;

include/xdpw.h

@@ -3,6 +3,7 @@
 
 #include <wayland-client.h>
 #include <systemd/sd-bus.h>
+#include "logger.h"
 
 struct xdpw_request {
 	sd_bus_slot *slot;

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',

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);
+
+}

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=<name>                       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=<loglevel>        Select log level (default is ERROR).\n"
+"                                     QUIET, ERROR, WARN, INFO, DEBUG, TRACE\n"
+"    -o, --output=<name>              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;
 		}
 	}

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;
 	}

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;
 	}

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;
 	}
 }

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);

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;
 	}