kern_error_monitor.c

// SPDX-License-Identifier: GPL-2.0
/*
 * kern_error_monitor.c - Userspace daemon that loads the BPF program
 * and prints KERN_ERR messages as they occur.
 *
 * Hybrid approach:
 *   - BPF kprobe on vprintk_emit captures PID, process name, and device
 *     info at function entry (before the message is formatted).
 *   - /dev/kmsg provides the fully formatted message text after the
 *     kernel stores it.
 *   - Events are correlated by timestamp: BPF events always arrive
 *     before the corresponding /dev/kmsg entry, so a simple FIFO
 *     queue with timestamp sanity check works for matching.
 */
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <signal.h>
#include <unistd.h>
#include <fcntl.h>
#include <errno.h>
#include <poll.h>
#include <bpf/libbpf.h>

#include "kern_error_monitor.h"
#include "kern_error_monitor.skel.h"

/* Maximum BPF events to cache for correlation */
#define BPF_CACHE_SIZE 64

/*
 * Maximum timestamp difference (ns) for BPF/kmsg correlation.
 * The BPF kprobe fires at vprintk_emit entry; the message is stored
 * in the kernel log buffer within the same function call, so the gap
 * is typically sub-microsecond.  50ms gives ample headroom.
 */
#define TS_MATCH_WINDOW_NS (50ULL * 1000 * 1000)

/* /dev/kmsg read buffer — kernel records are at most ~8 KiB */
#define KMSG_BUF_SIZE 8192

static volatile sig_atomic_t exiting;

static void sig_handler(int sig)
{
	exiting = 1;
}

/* ------------------------------------------------------------------ */
/* BPF event FIFO cache                                               */
/* ------------------------------------------------------------------ */

struct bpf_cached_event {
	unsigned int pid;
	unsigned int is_dev_err;
	unsigned long long ts_ns;
	char comm[TASK_COMM_LEN];
	char dev_subsystem[MAX_SUBSYS_LEN];
	char dev_device[MAX_DEV_LEN];
};

static struct bpf_cached_event bpf_cache[BPF_CACHE_SIZE];
static int cache_head;   /* next slot to read  */
static int cache_tail;   /* next slot to write */
static int cache_count;

static void cache_push(const struct event *e)
{
	struct bpf_cached_event *c = &bpf_cache[cache_tail];

	if (cache_count == BPF_CACHE_SIZE) {
		/* Overwrite oldest entry */
		cache_head = (cache_head + 1) % BPF_CACHE_SIZE;
		cache_count--;
	}

	c->pid = e->pid;
	c->is_dev_err = e->is_dev_err;
	c->ts_ns = e->ts_ns;
	memcpy(c->comm, e->comm, sizeof(c->comm));
	memcpy(c->dev_subsystem, e->dev_subsystem, sizeof(c->dev_subsystem));
	memcpy(c->dev_device, e->dev_device, sizeof(c->dev_device));

	cache_tail = (cache_tail + 1) % BPF_CACHE_SIZE;
	cache_count++;
}

/*
 * Try to dequeue a cached BPF event whose timestamp is close to
 * (and at most TS_MATCH_WINDOW_NS before) the given /dev/kmsg
 * timestamp.  Stale entries that are too old are discarded.
 *
 * Returns 1 if matched (fills *out), 0 otherwise.
 */
static int cache_match(unsigned long long kmsg_ts_ns,
		       struct bpf_cached_event *out)
{
	while (cache_count > 0) {
		struct bpf_cached_event *c = &bpf_cache[cache_head];

		/* BPF timestamp must be <= kmsg timestamp (fires before) */
		if (c->ts_ns <= kmsg_ts_ns &&
		    (kmsg_ts_ns - c->ts_ns) < TS_MATCH_WINDOW_NS) {
			*out = *c;
			cache_head = (cache_head + 1) % BPF_CACHE_SIZE;
			cache_count--;
			return 1;
		}

		/*
		 * If the oldest cached event is too old, discard it and
		 * try the next one.  Its /dev/kmsg counterpart was either
		 * not KERN_ERR or was missed.
		 */
		if (c->ts_ns + TS_MATCH_WINDOW_NS < kmsg_ts_ns) {
			cache_head = (cache_head + 1) % BPF_CACHE_SIZE;
			cache_count--;
			continue;
		}

		/* Event is newer than kmsg — don't discard, no match yet */
		break;
	}

	return 0;
}

/* ------------------------------------------------------------------ */
/* BPF ring buffer callback                                           */
/* ------------------------------------------------------------------ */

static int handle_event(void *ctx, void *data, size_t data_sz)
{
	const struct event *e = data;

	cache_push(e);
	return 0;
}

/* ------------------------------------------------------------------ */
/* /dev/kmsg parser                                                   */
/* ------------------------------------------------------------------ */

/*
 * Parse one /dev/kmsg record.
 * Format: "priority,sequence,timestamp_us,flags;message\n"
 *
 * Returns 0 on success, -1 on parse error.
 */
static int parse_kmsg(const char *buf, int *level,
		      unsigned long long *ts_us, char *msg, size_t msg_sz)
{
	unsigned long long priority;
	const char *p, *semi;

	/* priority */
	priority = strtoull(buf, (char **)&p, 10);
	if (*p != ',')
		return -1;
	p++;

	/* sequence — skip */
	(void)strtoull(p, (char **)&p, 10);
	if (*p != ',')
		return -1;
	p++;

	/* timestamp (microseconds since boot) */
	*ts_us = strtoull(p, (char **)&p, 10);
	if (*p != ',' && *p != ';')
		return -1;

	/* skip to semicolon */
	semi = strchr(p, ';');
	if (!semi)
		return -1;
	semi++;  /* past ';' */

	*level = priority & 7;

	/* copy message, strip trailing newline */
	strncpy(msg, semi, msg_sz - 1);
	msg[msg_sz - 1] = '\0';
	size_t len = strlen(msg);
	if (len > 0 && msg[len - 1] == '\n')
		msg[len - 1] = '\0';

	return 0;
}

/* ------------------------------------------------------------------ */
/* libbpf logging                                                     */
/* ------------------------------------------------------------------ */

static int libbpf_print_fn(enum libbpf_print_level level, const char *format,
			    va_list args)
{
	if (level == LIBBPF_DEBUG)
		return 0;
	return vfprintf(stderr, format, args);
}

/* ------------------------------------------------------------------ */
/* main                                                               */
/* ------------------------------------------------------------------ */

int main(int argc, char **argv)
{
	struct kern_error_monitor_bpf *skel;
	struct ring_buffer *rb = NULL;
	struct pollfd pfd;
	int kmsg_fd = -1;
	char kmsg_buf[KMSG_BUF_SIZE];
	int err;

	libbpf_set_print(libbpf_print_fn);

	signal(SIGINT, sig_handler);
	signal(SIGTERM, sig_handler);

	/* Open BPF application */
	skel = kern_error_monitor_bpf__open();
	if (!skel) {
		fprintf(stderr, "Failed to open BPF skeleton\n");
		return 1;
	}

	/* Load and verify BPF program */
	err = kern_error_monitor_bpf__load(skel);
	if (err) {
		fprintf(stderr, "Failed to load BPF skeleton: %d\n", err);
		goto cleanup;
	}

	/* Attach kprobe to vprintk_emit */
	err = kern_error_monitor_bpf__attach(skel);
	if (err) {
		fprintf(stderr, "Failed to attach BPF skeleton: %d\n", err);
		goto cleanup;
	}

	/* Set up ring buffer — we call ring_buffer__consume() manually */
	rb = ring_buffer__new(bpf_map__fd(skel->maps.events), handle_event,
			      NULL, NULL);
	if (!rb) {
		err = -1;
		fprintf(stderr, "Failed to create ring buffer\n");
		goto cleanup;
	}

	/* Open /dev/kmsg for fully formatted kernel messages */
	kmsg_fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
	if (kmsg_fd < 0) {
		fprintf(stderr, "Failed to open /dev/kmsg: %s\n",
			strerror(errno));
		err = -1;
		goto cleanup;
	}

	/* Seek to end — only process messages generated after startup */
	if (lseek(kmsg_fd, 0, SEEK_END) < 0) {
		fprintf(stderr, "Failed to seek /dev/kmsg: %s\n",
			strerror(errno));
		err = -1;
		goto cleanup;
	}

	printf("Monitoring kernel error messages (KERN_ERR)...\n");
	printf("Press Ctrl-C to exit.\n\n");

	pfd.fd = kmsg_fd;
	pfd.events = POLLIN;

	while (!exiting) {
		int ret;

		/* Drain any pending BPF events into cache */
		ring_buffer__consume(rb);

		/* Wait for /dev/kmsg data (or timeout for signal check) */
		ret = poll(&pfd, 1, 100);
		if (ret < 0) {
			if (errno == EINTR)
				continue;
			fprintf(stderr, "poll error: %s\n", strerror(errno));
			err = -1;
			break;
		}

		if (ret == 0)
			continue;

		/* Drain BPF ring buffer again — events arriving between
		 * the first consume and the poll wakeup are captured. */
		ring_buffer__consume(rb);

		/* Read all available /dev/kmsg entries */
		while (!exiting) {
			ssize_t n = read(kmsg_fd, kmsg_buf,
					 sizeof(kmsg_buf) - 1);
			if (n < 0) {
				if (errno == EAGAIN || errno == EWOULDBLOCK)
					break;
				if (errno == EPIPE) {
					/* Kernel ring buffer overrun — seek
					 * forward to current head */
					lseek(kmsg_fd, 0, SEEK_END);
					break;
				}
				if (errno == EINTR)
					continue;
				fprintf(stderr, "read /dev/kmsg: %s\n",
					strerror(errno));
				err = -1;
				goto cleanup;
			}

			kmsg_buf[n] = '\0';

			/* Skip continuation lines (multiline messages) */
			if (kmsg_buf[0] == ' ')
				continue;

			int level;
			unsigned long long ts_us;
			char msg[KMSG_BUF_SIZE];

			if (parse_kmsg(kmsg_buf, &level, &ts_us,
				       msg, sizeof(msg)) < 0)
				continue;

			if (level != KERN_ERR_LEVEL)
				continue;

			/* Correlate with a cached BPF event */
			struct bpf_cached_event bpf_ev;
			unsigned long long ts_ns = ts_us * 1000ULL;
			int matched = cache_match(ts_ns, &bpf_ev);

			unsigned long long secs = ts_us / 1000000ULL;
			unsigned long long usecs = ts_us % 1000000ULL;

			if (matched) {
				printf("[%5llu.%06llu] %-60s (pid=%u %s)\n",
				       secs, usecs, msg,
				       bpf_ev.pid, bpf_ev.comm);
			} else {
				printf("[%5llu.%06llu] %s\n",
				       secs, usecs, msg);
			}

			fflush(stdout);
		}
	}

cleanup:
	if (kmsg_fd >= 0)
		close(kmsg_fd);
	ring_buffer__free(rb);
	kern_error_monitor_bpf__destroy(skel);
	return err < 0 ? 1 : 0;
}