From 1e508f9168ad4a171046ca59b241adb0d0039459 Mon Sep 17 00:00:00 2001 From: Joachim Wiberg Date: Fri, 7 Aug 2026 13:58:53 +0200 Subject: [PATCH] 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 --- libink/Makefile.am | 2 +- libink/builtin.c | 1 + libink/connection.c | 3 +++ libink/dispatch.c | 15 +++++++++++++++ libink/internal.h | 5 +++++ libink/link.h | 14 ++++++++++++++ libink/log.c | 40 ++++++++++++++++++++++++++++++++++++++++ libink/server.c | 4 ++++ src/dbus.c | 11 +++++++++++ 9 files changed, 94 insertions(+), 1 deletion(-) create mode 100644 libink/log.c diff --git a/libink/Makefile.am b/libink/Makefile.am index e2f46e3a..e81d921f 100644 --- a/libink/Makefile.am +++ b/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 diff --git a/libink/builtin.c b/libink/builtin.c index e3e7bae7..fa511c1a 100644 --- a/libink/builtin.c +++ b/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"); diff --git a/libink/connection.c b/libink/connection.c index 3fe799bc..0a2327dd 100644 --- a/libink/connection.c +++ b/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. */ diff --git a/libink/dispatch.c b/libink/dispatch.c index 44642d7b..c09106f0 100644 --- a/libink/dispatch.c +++ b/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"); diff --git a/libink/internal.h b/libink/internal.h index 5f0f778a..7df8da91 100644 --- a/libink/internal.h +++ b/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); diff --git a/libink/link.h b/libink/link.h index afdd5d30..a3a447ba 100644 --- a/libink/link.h +++ b/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, diff --git a/libink/log.c b/libink/log.c new file mode 100644 index 00000000..226e263c --- /dev/null +++ b/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 + * SPDX-License-Identifier: MIT + */ + +#include +#include + +#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); +} diff --git a/libink/server.c b/libink/server.c index cb1cd790..9c32c5ce 100644 --- a/libink/server.c +++ b/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; diff --git a/src/dbus.c b/src/dbus.c index c42cf0e5..a0930992 100644 --- a/src/dbus.c +++ b/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;