libink: trace connections, calls, and authorization decisions

The legacy socket logs a line per command under initctl debug; the bus
logged nothing, so the transport that now carries most of initctl was
the one you could not watch.

libink gets a logger hook rather than a dependency on Finit's: it
passes the emitting function and a formatted message, and dbus.c hands
both to logit() so the two sources read alike.  Trace points cover the
connection lifecycle, every inbound call, and why a call was refused.

Signed-off-by: Joachim Wiberg <troglobit@gmail.com>

libink/Makefile.am

@@ -11,7 +11,7 @@ libink_la_SOURCES        = server.c auth.c connection.c \
                            dispatch.c builtin.c          \
                            match.c                       \
                            path.c                        \
-                           client.c io.c                 \
+                           client.c io.c log.c           \
                            link.h path.h internal.h
 
 libink_la_CPPFLAGS       = -D_GNU_SOURCE -D_DEFAULT_SOURCE -D_BSD_SOURCE

libink/builtin.c

@@ -468,6 +468,7 @@ int __handle_builtin(link_connection_t *conn, const struct link_msg *m)
 	    (!strcmp(m->member, "Hello") ||
 	     !strcmp(m->member, "AddMatch") ||
 	     !strcmp(m->member, "RemoveMatch"))) {
+		__dbg("%s is the broker's to answer, not ours", m->member);
 		return __send_error(conn, m,
 			"org.freedesktop.DBus.Error.AccessDenied",
 			"Handled by the message bus, not by this peer");

libink/connection.c

@@ -77,6 +77,8 @@ int link_connection_call(link_connection_t *conn, const char *destination,
 	if (blen > 0 && __io_write_all(conn->fd, body, (size_t)blen) < 0)
 		return -1;
 
+	__dbg("calling %s.%s on %s, serial %u", interface ? interface : "-",
+	      member, destination ? destination : "peer", serial);
 
 	conn->pending[i].used     = 1;
 	conn->pending[i].serial   = serial;
@@ -93,6 +95,7 @@ void link_connection_close(link_connection_t *conn)
 	if (!conn)
 		return;
 
+	__dbg("closing peer on fd %d", conn->fd);
 
 	/* Anything waiting on this connection has to be told, or a parked
 	 * call sits forever and its caller never hears back. */

libink/dispatch.c

@@ -341,6 +341,7 @@ static void deliver_reply(link_connection_t *conn, const struct link_msg *m)
 			break;
 	}
 	if (i == LINK_PENDING_CAP) {
+		__dbg("unsolicited reply, serial %u", m->reply_serial);
 		return;
 	}
 
@@ -449,6 +450,7 @@ void link_uid_resolved(link_server_t *server, link_authz_t tok, uid_t uid)
 	if (!conn || __msg_parse(buf, len, &msg) <= 0)
 		return;
 
+	__dbg("resumed %s, caller uid %d", msg.member ? msg.member : "call", (int)uid);
 	(void)dispatch_call(conn, &msg, NULL, 0, &uid);
 }
 
@@ -500,6 +502,7 @@ static int resolve_caller(link_connection_t *conn, const struct link_msg *m,
 	 * resolver to remember it: a truncated sender key would let two
 	 * callers share one identity. */
 	if (strlen(m->sender) >= LINK_SENDER_MAX) {
+		__dbg("sender name too long, refusing to identify it");
 		return -1;
 	}
 
@@ -512,6 +515,8 @@ static int resolve_caller(link_connection_t *conn, const struct link_msg *m,
 	rc = srv->uid_resolver(conn, m->sender, tok, uid, srv->uid_userdata);
 	if (rc != 1)
 		unpark(p);
+	else
+		__dbg("parked %s from %s, awaiting caller uid", m->member, m->sender);
 
 	return rc;
 }
@@ -533,11 +538,15 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 	call_uid = known_uid ? *known_uid : conn->peer_uid;
 
 	if (!m->path || !m->member) {
+		__dbg("malformed call, no path or member");
 		return __send_error(conn, m,
 			"org.freedesktop.DBus.Error.InvalidArgs",
 			"Method call without path or member");
 	}
 
+	__dbg("call %s %s.%s from %s", m->path,
+	      m->interface ? m->interface : "-", m->member,
+	      m->sender ? m->sender : "peer");
 
 	/* Built-in DBus interfaces (Hello, Ping, Introspect, Properties)
 	 * are handled here before object-tree lookup, which means they
@@ -551,6 +560,7 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 
 	o = find_object(conn->server, m->path);
 	if (!o) {
+		__dbg("no such object %s", m->path);
 		return __send_error(conn, m,
 			"org.freedesktop.DBus.Error.UnknownObject",
 			"No such object");
@@ -558,6 +568,7 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 
 	meth = resolve(o, m->interface, m->member, &e);
 	if (!meth) {
+		__dbg("no such method %s on %s", m->member, m->path);
 		return __send_error(conn, m,
 			"org.freedesktop.DBus.Error.UnknownMethod",
 			"No such method on this object");
@@ -569,6 +580,7 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 		const char *want = meth->in_sig ? meth->in_sig : "";
 
 		if (strcmp(got, want) != 0) {
+			__dbg("%s takes '%s', caller sent '%s'", m->member, want, got);
 			return __send_error(conn, m,
 				"org.freedesktop.DBus.Error.InvalidArgs",
 				"Argument signature mismatch");
@@ -591,6 +603,7 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 				/* Not a permission problem: root may well
 				 * be asking, we just have no slot to find
 				 * out in.  Say so, it is retryable. */
+				__dbg("no free slot to identify %s", m->sender);
 				return __send_error(conn, m,
 					"org.freedesktop.DBus.Error.LimitsExceeded",
 					"Too many calls awaiting authorization");
@@ -600,6 +613,8 @@ static int dispatch_call(link_connection_t *conn, const struct link_msg *m,
 		}
 
 		if (!caller_may(conn->server, call_uid)) {
+			__dbg("denied %s, caller uid %d is not privileged",
+			      m->member, (int)call_uid);
 			return __send_error(conn, m,
 				"org.freedesktop.DBus.Error.AccessDenied",
 				"Caller is not privileged for this method");

libink/internal.h

@@ -160,6 +160,11 @@ struct link_connection {
 	struct link_server  *server;	/* back-pointer for dispatch */
 };
 
+/* log.c — tracing, no-op unless the embedder installed a callback. */
+void __log(const char *func, const char *fmt, ...)
+	__attribute__((format(printf, 2, 3)));
+#define __dbg(fmt, ...)  __log(__func__, fmt, ##__VA_ARGS__)
+
 /* io.c — shared EINTR-resilient I/O loops. */
 int  __io_write_all(int fd, const void *buf, size_t len);
 int  __io_read_full(int fd, void *buf,       size_t len);

libink/link.h

@@ -88,6 +88,20 @@ typedef struct {
 	size_t         body_len;
 } link_reply_t;
 
+/* ----------  debug tracing  ---------- */
+
+/* Receives one line per connection, method call, and authorization
+ * decision.  `func` is the libink function that emitted it, so a host
+ * can format it the way it formats its own traces.
+ *
+ * With no logger installed, the default, a trace point costs one NULL
+ * test.  With one installed the message is formatted before the host
+ * sees it, so a host that only wants tracing sometimes should install
+ * and remove the callback rather than discard by level. */
+typedef void (*link_log_cb_t)(void *userdata, const char *func, const char *msg);
+
+void link_set_logger(link_log_cb_t cb, void *userdata);
+
 /* ----------  caller identity on a broker connection  ---------- */
 
 /* Handle for a call parked while its caller is identified.  Opaque,

libink/log.c

@@ -0,0 +1,40 @@
+/* libink — optional debug tracing, routed to whoever embeds us.
+ *
+ * libink has no logger of its own by design: it must not depend on the
+ * host's logging, and PID 1 already has one.  The embedder installs a
+ * callback and gets a line per connection, call, and authorization
+ * decision.  Formatting happens before the callback, so an embedder
+ * that wants tracing off should uninstall rather than filter.
+ *
+ * Copyright (c) 2026  Joachim Wiberg <troglobit@gmail.com>
+ * SPDX-License-Identifier: MIT
+ */
+
+#include <stdarg.h>
+#include <stdio.h>
+
+#include "internal.h"
+
+static link_log_cb_t  logger;
+static void          *logger_userdata;
+
+void link_set_logger(link_log_cb_t cb, void *userdata)
+{
+	logger          = cb;
+	logger_userdata = userdata;
+}
+
+void __log(const char *func, const char *fmt, ...)
+{
+	char    msg[256];
+	va_list ap;
+
+	if (!logger)
+		return;
+
+	va_start(ap, fmt);
+	vsnprintf(msg, sizeof(msg), fmt, ap);
+	va_end(ap);
+
+	logger(logger_userdata, func, msg);
+}

libink/server.c

@@ -60,6 +60,7 @@ int link_server_new(link_server_t **out, const char *path, mode_t mode)
 	 * permissive.  Who may connect is the caller's policy to set;
 	 * per-method authorization happens later in dispatch via
 	 * SO_PEERCRED. */
+	__dbg("binding %s, mode %04o", path, (unsigned)mode);
 	{
 		mode_t oldmask = umask(0777 & ~mode);
 		int    rc      = bind(fd, (struct sockaddr *)&sun, sizeof(sun));
@@ -159,6 +160,7 @@ int link_server_accept(link_server_t *srv, link_connection_t **out)
 
 	__auth_generate_guid(conn->guid);
 
+	__dbg("new peer on fd %d, uid %d", cfd, (int)conn->peer_uid);
 
 	*out = conn;
 	return 0;
@@ -216,6 +218,8 @@ link_connection_t *link_server_attach(link_server_t *srv, int fd, uid_t peer_uid
 	conn->broker   = !!(attach_flags & LINK_ATTACH_BROKER);
 	__auth_generate_guid(conn->guid);
 
+	__dbg("attached %s peer on fd %d, uid %d",
+	      conn->broker ? "broker" : "external", fd, (int)peer_uid);
 
 	return conn;
 

src/dbus.c

@@ -73,6 +73,15 @@ static struct peer        *sysbus_peer;
 static void sysbus_probe(void);
 static void sender_cache_flush(void);
 
+/* libink has no logger of its own, so give it ours.  The func name it
+ * passes takes the place of dbg()'s __func__, which would otherwise
+ * always read "link_log_cb". */
+static void link_log_cb(void *userdata, const char *func, const char *msg)
+{
+	(void)userdata;
+	logit(LOG_DEBUG, "%s():%s", func, msg);
+}
+
 static void peer_drop(struct peer *p)
 {
 	int was_sysbus = p == sysbus_peer;
@@ -1526,6 +1535,8 @@ int dbus_init(uev_ctx_t *ctx)
 	/* Same access policy as INIT_SOCKET: the bus reaches every
 	 * service operation initctl does, so --with-group has to gate
 	 * both or it gates neither. */
+	link_set_logger(link_log_cb, NULL);
+
 	if (link_server_new(&server, FINIT_BUS_SOCKET, 0660) < 0) {
 		err(1, "Failed binding D-Bus socket %s", FINIT_BUS_SOCKET);
 		return 1;