feat: log continuous debug messages into per-device buffers

Instead of exposing to consumers write streaming log data into a per-device
buffer that gets created on request and destroyed after the buffer has been
written to the log.

Passing a NULL string to the internal continuous log function triggers a write
of the buffer to the log.

BREAKING CHANGE: continuous log function is moved from log header to private
header.

alloc.c

@@ -581,23 +581,21 @@ static void log_no_reuse(struct liftoff_output *output)
 	}
 }
 
-static void log_plane_type_change(uint32_t base, uint32_t cmp)
+static void log_plane_type_change(struct liftoff_device *device,
+								  uint32_t base, uint32_t cmp)
 {
 	switch (base) {
 	case DRM_PLANE_TYPE_PRIMARY:
-		liftoff_log_cnt(LIFTOFF_DEBUG, " <p|");
+		debug_cnt(device, " <p|");
-		liftoff_log_cnt(LIFTOFF_DEBUG,
+		debug_cnt(device, cmp == DRM_PLANE_TYPE_OVERLAY ? "o>" : "c>");
-						cmp == DRM_PLANE_TYPE_OVERLAY ? "o>" : "c>");
 		break;
 	case DRM_PLANE_TYPE_CURSOR:
-		liftoff_log_cnt(LIFTOFF_DEBUG, " <c|");
+		debug_cnt(device, " <c|");
-		liftoff_log_cnt(LIFTOFF_DEBUG,
+		debug_cnt(device, cmp == DRM_PLANE_TYPE_PRIMARY ? "p>" : "o>");
-						cmp == DRM_PLANE_TYPE_PRIMARY ? "p>" : "o>");
 		break;
 	case DRM_PLANE_TYPE_OVERLAY:
-		liftoff_log_cnt(LIFTOFF_DEBUG, " <o|");
+		debug_cnt(device, " <o|");
-		liftoff_log_cnt(LIFTOFF_DEBUG,
+		debug_cnt(device, cmp == DRM_PLANE_TYPE_PRIMARY ? "p>" : "c>");
-						cmp == DRM_PLANE_TYPE_PRIMARY ? "p>" : "c>");
 		break;
 	}
 }
@@ -615,12 +613,13 @@ static void log_planes(struct liftoff_device *device,
 		return;
 	}
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\nAvailable planes");
+	debug_cnt(device, "Available planes");
 	if (output) {
-		liftoff_log(LIFTOFF_DEBUG, " (on output %"PRIu32 "):", output->crtc_id);
+		debug_cnt(device, " (on output %"PRIu32 "):", output->crtc_id);
 	} else {
-		liftoff_log(LIFTOFF_DEBUG, ":");
+		debug_cnt(device, ":");
 	}
+	debug_cnt(device, NULL);
 
 	liftoff_list_for_each(plane, &device->planes, link) {
 		bool active = false;
@@ -653,8 +652,8 @@ static void log_planes(struct liftoff_device *device,
 			}
 		}
 
-		liftoff_log_cnt(LIFTOFF_DEBUG, "  Plane %"PRIu32 "%s", plane->id,
+		debug_cnt(device, "  Plane %"PRIu32 "%s", plane->id,
-			active ? ":" : " (inactive):");
+				  active ? ":" : " (inactive):");
 
 		max_per_line = active ? 1 : 4;
 		per_line = max_per_line - 1;
@@ -663,21 +662,22 @@ static void log_planes(struct liftoff_device *device,
 			char *name;
 
 			if (++per_line == max_per_line) {
-				liftoff_log_cnt(LIFTOFF_DEBUG, "\n   ");
+				debug_cnt(device, NULL);
+				debug_cnt(device, "   ");
 				per_line = 0;
 			}
 
 			drm_prop = drmModeGetProperty(device->drm_fd,
 							  drm_props->props[i]);
 			if (drm_prop == NULL) {
-				liftoff_log_cnt(LIFTOFF_DEBUG, "ERR!");
+				debug_cnt(device, "ERR!");
 				continue;
 			}
 
 			name = drm_prop->name;
 
 			if (strcmp(name, "type") == 0) {
-				liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %s", name,
+				debug_cnt(device, " %s: %s", name,
 					value == DRM_PLANE_TYPE_PRIMARY ? "primary" :
 					value == DRM_PLANE_TYPE_CURSOR ? "cursor" : "overlay");
 				continue;
@@ -685,16 +685,16 @@ static void log_planes(struct liftoff_device *device,
 
 			if (strcmp(name, "CRTC_X") == 0 || strcmp(name, "CRTC_Y") == 0
 					|| strcmp(name, "IN_FENCE_FD") == 0) {
-				liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIi32, name, (int32_t)value);
+				debug_cnt(device, " %s: %"PRIi32, name, (int32_t)value);
 				continue;
 			}
 
 			if (strcmp(name, "SRC_W") == 0 || strcmp(name, "SRC_H") == 0) {
 				value = value >> 16;
 			}
-			liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIu64, name, value);
+			debug_cnt(device, " %s: %"PRIu64, name, value);
 		}
-		liftoff_log_cnt(LIFTOFF_DEBUG, "\n");
+		debug_cnt(device, NULL);
 	}
 }
 
@@ -704,7 +704,7 @@ static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req)
 	uint32_t debug_type = DRM_PLANE_TYPE_PRIMARY;
 	bool compatible;
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\nReset planes:");
+	debug_cnt(device, "\nReset planes:");
 
 	liftoff_list_for_each(plane, &device->planes, link) {
 		if (plane->layer != NULL) {
@@ -713,19 +713,21 @@ static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req)
 
 		if (log_has(LIFTOFF_DEBUG)) {
 			if (plane->type != debug_type) {
-				log_plane_type_change(debug_type, plane->type);
+				log_plane_type_change(device, debug_type, plane->type);
 				debug_type = plane->type;
 			}
-			liftoff_log_cnt(LIFTOFF_DEBUG, " %"PRIu32, plane->id);
+			debug_cnt(device, " %"PRIu32, plane->id);
 		}
 
 		if (!plane_apply(plane, NULL, req, &compatible)) {
+			debug_cnt(device, "... Error resetting: %"PRIu32, plane->id);
+			debug_cnt(device, NULL);
 			return false;
 		}
 		assert(compatible);
 	}
 
-	liftoff_log(LIFTOFF_DEBUG, "\n");
+	debug_cnt(device, NULL);
 	return true;
 }
 

device.c

@@ -13,14 +13,14 @@ struct liftoff_device *liftoff_device_create(int drm_fd)
 	drmModePlaneRes *drm_plane_res;
 	uint32_t i;
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\nCreating device for fd %d. ", drm_fd);
-
 	device = calloc(1, sizeof(*device));
 	if (device == NULL) {
 		liftoff_log_errno(LIFTOFF_ERROR, "calloc");
 		return NULL;
 	}
 
+	liftoff_log(LIFTOFF_DEBUG, "\nCreating device for fd %d. ", drm_fd);
+
 	liftoff_list_init(&device->planes);
 	liftoff_list_init(&device->outputs);
 
@@ -63,9 +63,9 @@ struct liftoff_device *liftoff_device_create(int drm_fd)
 
 	for (i = 0; i < drm_plane_res->count_planes; i++) {
 		if (i < 9 && drm_plane_res->count_planes >= 9) {
-			liftoff_log_cnt(LIFTOFF_DEBUG, " ");
+			debug_cnt(device, " ");
 		}
-		liftoff_log_cnt(LIFTOFF_DEBUG, "[%d] ", i + 1);
+		debug_cnt(device, "[%d] ", i + 1);
 		if (plane_create(device, drm_plane_res->planes[i]) == NULL) {
 			liftoff_device_destroy(device);
 			return NULL;
@@ -73,8 +73,6 @@ struct liftoff_device *liftoff_device_create(int drm_fd)
 	}
 	drmModeFreePlaneResources(drm_plane_res);
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\n");
-
 	return device;
 }
 
@@ -91,6 +89,7 @@ void liftoff_device_destroy(struct liftoff_device *device)
 		plane_destroy(plane);
 	}
 	free(device->crtcs);
+	free(device->log_buf);
 	free(device);
 }
 

include/libliftoff.h

@@ -74,7 +74,7 @@ enum liftoff_log_importance {
 	LIFTOFF_DEBUG,
 };
 
-typedef void (*liftoff_log_func)(enum liftoff_log_importance importance, bool newline,
+typedef void (*liftoff_log_func)(enum liftoff_log_importance importance,
 				 const char *fmt, va_list args);
 
 void liftoff_log_init(enum liftoff_log_importance verbosity,

include/log.h

@@ -13,8 +13,9 @@ bool log_has(enum liftoff_log_importance verbosity);
 
 void liftoff_log(enum liftoff_log_importance verbosity,
 		 const char *format, ...) _LIFTOFF_ATTRIB_PRINTF(2, 3);
-void liftoff_log_cnt(enum liftoff_log_importance verbosity,
-		 const char *format, ...) _LIFTOFF_ATTRIB_PRINTF(2, 3);
 void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg);
 
+void debug_cnt(struct liftoff_device *device, const char *format, ...)
+_LIFTOFF_ATTRIB_PRINTF(2, 3);
+
 #endif

include/private.h

@@ -19,6 +19,10 @@ struct liftoff_device {
 	size_t crtcs_len;
 
 	int page_flip_counter;
+
+	char *log_buf;
+	size_t log_buf_len;
+	size_t log_buf_index;
 };
 
 struct liftoff_output {

log.c

@@ -1,17 +1,17 @@
 #include <errno.h>
 #include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 #include "log.h"
+#include "private.h"
 
 static enum liftoff_log_importance log_importance = LIFTOFF_ERROR;
 
-static void log_stderr(enum liftoff_log_importance verbosity, bool newline, const char *fmt,
+static void log_stderr(enum liftoff_log_importance verbosity, const char *fmt,
 		       va_list args)
 {
 	vfprintf(stderr, fmt, args);
-	if (newline) {
+	fprintf(stderr, "\n");
-		fprintf(stderr, "\n");
-	}
 }
 
 static liftoff_log_func log_callback = log_stderr;
@@ -39,19 +39,7 @@ void liftoff_log(enum liftoff_log_importance verbosity, const char *fmt, ...)
 
 	va_list args;
 	va_start(args, fmt);
-	log_callback(verbosity, true, fmt, args);
+	log_callback(verbosity, fmt, args);
-	va_end(args);
-}
-
-void liftoff_log_cnt(enum liftoff_log_importance verbosity, const char *fmt, ...)
-{
-	if (!log_has(verbosity)) {
-		return;
-	}
-
-	va_list args;
-	va_start(args, fmt);
-	log_callback(verbosity, false, fmt, args);
 	va_end(args);
 }
 
@@ -59,3 +47,68 @@ void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg)
 {
 	liftoff_log(verbosity, "%s: %s", msg, strerror(errno));
 }
+
+
+void debug_cnt(struct liftoff_device *device, const char *fmt, ...)
+{
+	if (!log_has(LIFTOFF_DEBUG)) {
+		return;
+	}
+
+	if (fmt == NULL) {
+		if (device->log_buf == 0) {
+			return;
+		}
+		liftoff_log(LIFTOFF_DEBUG, "%s", device->log_buf);
+		free(device->log_buf);
+		device->log_buf = NULL;
+		device->log_buf_index = 0;
+		device->log_buf_len = 0;
+		return;
+	}
+
+	va_list args;
+	va_start(args, fmt);
+
+	if (device->log_buf == NULL) {
+		device->log_buf = malloc(4096);
+		if (device->log_buf == NULL) {
+			liftoff_log_errno(LIFTOFF_ERROR, "malloc");
+			goto cleanup_out;
+		}
+		device->log_buf_len = 4096 / sizeof(char);
+	}
+
+	do {
+		size_t max_len = device->log_buf_len - device->log_buf_index;
+		int ret;
+
+		ret = vsnprintf(device->log_buf + device->log_buf_index,
+						max_len, fmt, args);
+		if (ret < 0) {
+			goto cleanup_out;
+		}
+
+		if (ret - (int)max_len > 0) {
+			device->log_buf_index = device->log_buf_len;
+			device->log_buf_len *= 2;
+
+			if (realloc(device->log_buf, device->log_buf_len) == NULL) {
+				liftoff_log_errno(LIFTOFF_ERROR, "realloc");
+				goto cleanup_out;
+			}
+		} else {
+			device->log_buf_index += ret;
+			goto final_out;
+		}
+	} while (1);
+
+cleanup_out:
+	free(device->log_buf);
+	device->log_buf = NULL;
+	device->log_buf_index = 0;
+	device->log_buf_len = 0;
+
+final_out:
+	va_end(args);
+}

plane.c

@@ -30,7 +30,8 @@ static int guess_plane_zpos_from_type(struct liftoff_device *device,
 	return 0;
 }
 
-static void log_plane(struct liftoff_plane *plane)
+static void log_plane(struct liftoff_device *device,
+					  struct liftoff_plane *plane)
 {
 	size_t i;
 	int per_line = 0;
@@ -39,26 +40,29 @@ static void log_plane(struct liftoff_plane *plane)
 		return;
 	}
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "     type: ");
+	debug_cnt(device, "     type: ");
 	if (plane->type == DRM_PLANE_TYPE_PRIMARY) {
-		liftoff_log(LIFTOFF_DEBUG, "Primary");
+		debug_cnt(device, "Primary");
 	} else if (plane->type == DRM_PLANE_TYPE_CURSOR) {
-		liftoff_log(LIFTOFF_DEBUG, "Cursor");
+		debug_cnt(device, "Cursor");
 	} else {
-		liftoff_log(LIFTOFF_DEBUG, "Overlay");
+		debug_cnt(device, "Overlay");
 	}
+	debug_cnt(device, NULL);
+
 	liftoff_log(LIFTOFF_DEBUG, "     zpos: %"PRIu32, plane->zpos);
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "    props:");
+	debug_cnt(device, "    props:");
 	for (i = 0; i < plane->props_len; i++) {
 		if (per_line == 5) {
-			liftoff_log_cnt(LIFTOFF_DEBUG, "\n          ");
+			debug_cnt(device, NULL);
+			debug_cnt(device, "          ");
 			per_line = 0;
 		}
-		liftoff_log_cnt(LIFTOFF_DEBUG, " %s", plane->props[i].name);
+		debug_cnt(device, " %s", plane->props[i].name);
 		per_line++;
 	}
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\n");
+	debug_cnt(device, NULL);
 }
 
 struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id)
@@ -72,7 +76,8 @@ struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id)
 	uint64_t value;
 	bool has_type = false, has_zpos = false;
 
-	liftoff_log(LIFTOFF_DEBUG, "Plane %"PRIu32, id);
+	debug_cnt(device, "Plane %"PRIu32, id);
+	debug_cnt(device, NULL);
 
 	plane = calloc(1, sizeof(*plane));
 	if (plane == NULL) {
@@ -158,7 +163,7 @@ struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id)
 		}
 	}
 
-	log_plane(plane);
+	log_plane(device, plane);
 
 	return plane;
 }