libseat: Expand logging in all backends

2 files changed, 120 insertions, 61 deletions

diff --git a/libseat/backend/logind.c b/libseat/backend/logind.c
index 4ebeb17..c28165f 100644
--- a/libseat/backend/logind.c
+++ b/libseat/backend/logind.c
@@ -76,6 +76,7 @@ static int open_device(struct libseat *base, const char *path, int *fd) {
 
 	struct stat st;
 	if (stat(path, &st) < 0) {
+		log_errorf("Could not stat path '%s'", path);
 		return -1;
 	}
 
@@ -83,6 +84,7 @@ static int open_device(struct libseat *base, const char *path, int *fd) {
 				 "org.freedesktop.login1.Session", "TakeDevice", &error, &msg, "uu",
 				 major(st.st_rdev), minor(st.st_rdev));
 	if (ret < 0) {
+		log_errorf("Could not take device: %s", error.message);
 		tmpfd = -1;
 		goto out;
 	}
@@ -90,6 +92,7 @@ static int open_device(struct libseat *base, const char *path, int *fd) {
 	int paused = 0;
 	ret = sd_bus_message_read(msg, "hb", &tmpfd, &paused);
 	if (ret < 0) {
+		log_errorf("Could not parse D-Bus response: %s", strerror(-ret));
 		tmpfd = -1;
 		goto out;
 	}
@@ -98,12 +101,14 @@ static int open_device(struct libseat *base, const char *path, int *fd) {
 	// so we just clone it.
 	tmpfd = fcntl(tmpfd, F_DUPFD_CLOEXEC, 0);
 	if (tmpfd < 0) {
+		log_errorf("Could not duplicate fd: %s", strerror(errno));
 		tmpfd = -1;
 		goto out;
 	}
 
 	if (dev_is_drm(st.st_rdev)) {
 		session->has_drm++;
+		log_debugf("DRM device opened, current total: %d", session->has_drm);
 	}
 
 	*fd = tmpfd;
@@ -124,11 +129,13 @@ static int close_device(struct libseat *base, int device_id) {
 
 	struct stat st = {0};
 	if (fstat(fd, &st) < 0) {
+		log_errorf("Could not stat fd %d", fd);
 		close(fd);
 		return -1;
 	}
 	if (dev_is_drm(st.st_rdev)) {
 		session->has_drm--;
+		log_debugf("DRM device closed, current total: %d", session->has_drm);
 		assert(session->has_drm >= 0);
 	}
 	close(fd);
@@ -138,6 +145,9 @@ static int close_device(struct libseat *base, int device_id) {
 	int ret = sd_bus_call_method(session->bus, "org.freedesktop.login1", session->path,
 				     "org.freedesktop.login1.Session", "ReleaseDevice", &error,
 				     &msg, "uu", major(st.st_rdev), minor(st.st_rdev));
+	if (ret < 0) {
+		log_errorf("Could not close device: %s", error.message);
+	}
 
 	sd_bus_error_free(&error);
 	sd_bus_message_unref(msg);
@@ -159,6 +169,9 @@ static int switch_session(struct libseat *base, int s) {
 				     "/org/freedesktop/login1/seat/seat0",
 				     "org.freedesktop.login1.Seat", "SwitchTo", &error, &msg, "u",
 				     (uint32_t)s);
+	if (ret < 0) {
+		log_errorf("Could not switch session: %s", error.message);
+	}
 
 	sd_bus_error_free(&error);
 	sd_bus_message_unref(msg);
@@ -216,6 +229,7 @@ static int dispatch_background(struct libseat *base, int timeout) {
 	}
 	if (total_dispatched == 0 && timeout != 0) {
 		if (poll_connection(backend, timeout) == -1) {
+			log_errorf("Could not poll connection: %s", strerror(errno));
 			return -1;
 		}
 		while ((dispatched = sd_bus_process(backend->bus, NULL)) > 0) {
@@ -245,6 +259,9 @@ static bool session_activate(struct backend_logind *session) {
 
 	int ret = sd_bus_call_method(session->bus, "org.freedesktop.login1", session->path,
 				     "org.freedesktop.login1.Session", "Activate", &error, &msg, "");
+	if (ret < 0) {
+		log_errorf("Could not activate session: %s", error.message);
+	}
 
 	sd_bus_error_free(&error);
 	sd_bus_message_unref(msg);
@@ -258,6 +275,9 @@ static bool take_control(struct backend_logind *session) {
 	int ret = sd_bus_call_method(session->bus, "org.freedesktop.login1", session->path,
 				     "org.freedesktop.login1.Session", "TakeControl", &error, &msg,
 				     "b", false);
+	if (ret < 0) {
+		log_errorf("Could not take control of session: %s", error.message);
+	}
 
 	sd_bus_error_free(&error);
 	sd_bus_message_unref(msg);
@@ -271,8 +291,10 @@ static void set_active(struct backend_logind *backend, bool active) {
 
 	backend->active = active;
 	if (active) {
+		log_info("Enabling seat");
 		backend->seat_listener->enable_seat(&backend->base, backend->seat_listener_data);
 	} else {
+		log_info("Disabling seat");
 		backend->seat_listener->disable_seat(&backend->base, backend->seat_listener_data);
 	}
 }
@@ -284,21 +306,26 @@ static int pause_device(sd_bus_message *msg, void *userdata, sd_bus_error *ret_e
 	const char *type;
 	int ret = sd_bus_message_read(msg, "uus", &major, &minor, &type);
 	if (ret < 0) {
-		goto error;
+		log_errorf("Could not parse D-Bus response: %s", strerror(-ret));
+		return 0;
 	}
 
 	if (dev_is_drm(makedev(major, minor)) && strcmp(type, "gone") != 0) {
+		log_debugf("DRM device paused: %s", type);
 		assert(session->has_drm > 0);
 		set_active(session, false);
 	}
 
 	if (strcmp(type, "pause") == 0) {
-		sd_bus_call_method(session->bus, "org.freedesktop.login1", session->path,
-				   "org.freedesktop.login1.Session", "PauseDeviceComplete",
-				   ret_error, &msg, "uu", major, minor);
+		ret = sd_bus_call_method(session->bus, "org.freedesktop.login1", session->path,
+					 "org.freedesktop.login1.Session", "PauseDeviceComplete",
+					 ret_error, &msg, "uu", major, minor);
+		if (ret < 0) {
+			log_errorf("Could not send PauseDeviceComplete signal: %s",
+				   ret_error->message);
+		}
 	}
 
-error:
 	return 0;
 }
 
@@ -311,15 +338,16 @@ static int resume_device(sd_bus_message *msg, void *userdata, sd_bus_error *ret_
 	uint32_t major, minor;
 	ret = sd_bus_message_read(msg, "uuh", &major, &minor, &fd);
 	if (ret < 0) {
-		goto error;
+		log_errorf("Could not parse D-Bus response: %s", strerror(-ret));
+		return 0;
 	}
 
 	if (dev_is_drm(makedev(major, minor))) {
+		log_debug("DRM device resumed");
 		assert(session->has_drm > 0);
 		set_active(session, true);
 	}
 
-error:
 	return 0;
 }
 
@@ -370,6 +398,7 @@ static int session_properties_changed(sd_bus_message *msg, void *userdata, sd_bu
 				goto error;
 			}
 
+			log_debugf("Active state changed: %d", active);
 			set_active(session, active);
 			return 0;
 		} else {
@@ -402,22 +431,22 @@ static int session_properties_changed(sd_bus_message *msg, void *userdata, sd_bu
 							  "org.freedesktop.login1.Session",
 							  "Active", &error, 'b', &active);
 			if (ret < 0) {
+				log_errorf("Could not get 'Active' property: %s", error.message);
 				return 0;
 			}
 
+			log_debugf("Active state changed: %d", active);
 			set_active(session, active);
 			return 0;
 		}
 	}
 
+error:
 	if (ret < 0) {
-		goto error;
+		log_errorf("Could not parse D-Bus PropertiesChanged on session: %s", strerror(-ret));
 	}
 
 	return 0;
-
-error:
-	return 0;
 }
 
 static int seat_properties_changed(sd_bus_message *msg, void *userdata, sd_bus_error *ret_error) {
@@ -465,7 +494,7 @@ static int seat_properties_changed(sd_bus_message *msg, void *userdata, sd_bus_e
 			if (ret < 0) {
 				goto error;
 			}
-
+			log_debugf("CanGraphical state changed: %d", session->can_graphical);
 			return 0;
 		} else {
 			sd_bus_message_skip(msg, "{sv}");
@@ -491,18 +520,17 @@ static int seat_properties_changed(sd_bus_message *msg, void *userdata, sd_bus_e
 	while ((ret = sd_bus_message_read_basic(msg, 's', &s)) > 0) {
 		if (strcmp(s, "CanGraphical") == 0) {
 			session->can_graphical = sd_seat_can_graphical(session->seat);
+			log_debugf("CanGraphical state changed: %d", session->can_graphical);
 			return 0;
 		}
 	}
 
+error:
 	if (ret < 0) {
-		goto error;
+		log_errorf("Could not parse D-Bus PropertiesChanged on seat: %s", strerror(-ret));
 	}
 
 	return 0;
-
-error:
-	return 0;
 }
 
 static bool add_signal_matches(struct backend_logind *backend) {
@@ -514,24 +542,28 @@ static bool add_signal_matches(struct backend_logind *backend) {
 	ret = sd_bus_match_signal(backend->bus, NULL, logind, backend->path, session_interface,
 				  "PauseDevice", pause_device, backend);
 	if (ret < 0) {
+		log_errorf("Could not add D-Bus match: %s", strerror(-ret));
 		return false;
 	}
 
 	ret = sd_bus_match_signal(backend->bus, NULL, logind, backend->path, session_interface,
 				  "ResumeDevice", resume_device, backend);
 	if (ret < 0) {
+		log_errorf("Could not add D-Bus match: %s", strerror(-ret));
 		return false;
 	}
 
 	ret = sd_bus_match_signal(backend->bus, NULL, logind, backend->path, property_interface,
 				  "PropertiesChanged", session_properties_changed, backend);
 	if (ret < 0) {
+		log_errorf("Could not add D-Bus match: %s", strerror(-ret));
 		return false;
 	}
 
 	ret = sd_bus_match_signal(backend->bus, NULL, logind, backend->seat_path, property_interface,
 				  "PropertiesChanged", seat_properties_changed, backend);
 	if (ret < 0) {
+		log_errorf("Could not add D-Bus match: %s", strerror(-ret));
 		return false;
 	}
 
@@ -547,12 +579,14 @@ static bool find_session_path(struct backend_logind *session) {
 				 "org.freedesktop.login1.Manager", "GetSession", &error, &msg, "s",
 				 session->id);
 	if (ret < 0) {
+		log_errorf("Could not get session: %s", error.message);
 		goto out;
 	}
 
 	const char *path;
 	ret = sd_bus_message_read(msg, "o", &path);
 	if (ret < 0) {
+		log_errorf("Could not parse D-Bus response: %s", strerror(-ret));
 		goto out;
 	}
 	session->path = strdup(path);
@@ -573,12 +607,14 @@ static bool find_seat_path(struct backend_logind *session) {
 				 "org.freedesktop.login1.Manager", "GetSeat", &error, &msg, "s",
 				 session->seat);
 	if (ret < 0) {
+		log_errorf("Could not get seat: %s", error.message);
 		goto out;
 	}
 
 	const char *path;
 	ret = sd_bus_message_read(msg, "o", &path);
 	if (ret < 0) {
+		log_errorf("Could not parse D-Bus response: %s", strerror(-ret));
 		goto out;
 	}
 	session->seat_path = strdup(path);
@@ -593,10 +629,13 @@ out:
 static bool get_display_session(char **session_id) {
 	assert(session_id != NULL);
 	char *xdg_session_id = getenv("XDG_SESSION_ID");
+	int ret;
 
 	if (xdg_session_id) {
 		// This just checks whether the supplied session ID is valid
-		if (sd_session_is_active(xdg_session_id) < 0) {
+		ret = sd_session_is_active(xdg_session_id);
+		if (ret < 0) {
+			log_errorf("Could not check if session was active: %s", strerror(-ret));
 			goto error;
 		}
 		*session_id = strdup(xdg_session_id);
@@ -605,7 +644,7 @@ static bool get_display_session(char **session_id) {
 
 	// If there's a session active for the current process then just use
 	// that
-	int ret = sd_pid_get_session(getpid(), session_id);
+	ret = sd_pid_get_session(getpid(), session_id);
 	if (ret == 0) {
 		goto success;
 	}
@@ -614,6 +653,7 @@ static bool get_display_session(char **session_id) {
 	// active session itself
 	ret = sd_uid_get_display(getuid(), session_id);
 	if (ret < 0) {
+		log_errorf("Could not get primary session for user: %s", strerror(-ret));
 		goto error;
 	}
 
@@ -635,7 +675,7 @@ static int set_type(struct backend_logind *backend, const char *type) {
 				     "org.freedesktop.login1.Session", "SetType", &error, &msg, "s",
 				     type);
 	if (ret < 0) {
-		log_errorf("unable to set session type: %s", error.message);
+		log_errorf("Could not set session type: %s", error.message);
 	}
 
 	sd_bus_error_free(&error);
@@ -686,6 +726,7 @@ static struct libseat *logind_open_seat(struct libseat_seat_listener *listener,
 	backend->can_graphical = sd_seat_can_graphical(backend->seat);
 	while (!backend->can_graphical) {
 		if (poll_connection(backend, -1) == -1) {
+			log_errorf("Could not poll connection: %s", strerror(errno));
 			goto error;
 		}
 	}
diff --git a/libseat/backend/seatd.c b/libseat/backend/seatd.c
index 7b0b411..413282e 100644
--- a/libseat/backend/seatd.c
+++ b/libseat/backend/seatd.c
@@ -89,12 +89,14 @@ static struct backend_seatd *backend_seatd_from_libseat_backend(struct libseat *
 }
 
 static void handle_enable_seat(struct backend_seatd *backend) {
+	log_info("Enabling seat");
 	if (backend->seat_listener != NULL && backend->seat_listener->enable_seat != NULL) {
 		backend->seat_listener->enable_seat(&backend->base, backend->seat_listener_data);
 	}
 }
 
 static void handle_disable_seat(struct backend_seatd *backend) {
+	log_info("Disabling seat");
 	if (backend->seat_listener != NULL && backend->seat_listener->disable_seat != NULL) {
 		backend->seat_listener->disable_seat(&backend->base, backend->seat_listener_data);
 	}
@@ -103,11 +105,22 @@ static void handle_disable_seat(struct backend_seatd *backend) {
 static size_t read_header(struct connection *connection, uint16_t expected_opcode) {
 	struct proto_header header;
 	if (connection_get(connection, &header, sizeof header) == -1) {
+		log_error("Received invalid message: header too short");
 		return SIZE_MAX;
 	}
 	if (header.opcode != expected_opcode) {
 		connection_restore(connection, sizeof header);
-		errno = EBADMSG;
+		struct proto_server_error msg;
+		if (header.opcode != SERVER_ERROR) {
+			log_errorf("Received invalid message: expected opcode %d, received opcode %d",
+				   expected_opcode, header.opcode);
+			errno = EBADMSG;
+		} else if (connection_get(connection, &msg, sizeof msg) == -1) {
+			log_error("Received invalid message");
+			errno = EBADMSG;
+		} else {
+			errno = msg.error_code;
+		}
 		return SIZE_MAX;
 	}
 
@@ -161,7 +174,9 @@ static int dispatch_pending(struct backend_seatd *backend, int *opcode) {
 		switch (header.opcode) {
 		case SERVER_DISABLE_SEAT:
 		case SERVER_ENABLE_SEAT:
-			queue_event(backend, header.opcode);
+			if (queue_event(backend, header.opcode) == -1) {
+				return -1;
+			}
 			break;
 		default:
 			if (opcode != NULL &&
@@ -193,7 +208,10 @@ static int poll_connection(struct backend_seatd *backend, int timeout) {
 	int len = 0;
 	if (fd.revents & POLLIN) {
 		len = connection_read(&backend->connection);
-		if (len == 0 || (len == -1 && errno != EAGAIN)) {
+		if (len == 0) {
+			errno = EIO;
+			return -1;
+		} else if (len == -1 && errno != EAGAIN) {
 			return -1;
 		}
 	}
@@ -203,33 +221,20 @@ static int poll_connection(struct backend_seatd *backend, int timeout) {
 
 static int dispatch(struct backend_seatd *backend) {
 	if (connection_flush(&backend->connection) == -1) {
+		log_errorf("Could not flush connection: %s", strerror(errno));
 		return -1;
 	}
-	int opcode = 0;
-	while (dispatch_pending(backend, &opcode) == 0 && opcode == 0) {
+	int opcode = 0, res = 0;
+	while ((res = dispatch_pending(backend, &opcode)) == 0 && opcode == 0) {
 		if (poll_connection(backend, -1) == -1) {
+			log_errorf("Could not poll connection: %s", strerror(errno));
 			return -1;
 		}
 	}
-	return 0;
-}
-
-static void check_error(struct connection *connection) {
-	struct proto_header header;
-	if (connection_get(connection, &header, sizeof header) == -1) {
-		return;
-	}
-	if (header.opcode != SERVER_ERROR) {
-		errno = EBADMSG;
-		return;
-	}
-
-	struct proto_server_error msg;
-	if (connection_get(connection, &msg, sizeof msg) == -1) {
-		return;
+	if (res == -1) {
+		return -1;
 	}
-
-	errno = msg.error_code;
+	return 0;
 }
 
 static int get_fd(struct libseat *base) {
@@ -255,6 +260,7 @@ static int dispatch_background(struct libseat *base, int timeout) {
 	if (read > 0) {
 		dispatched += dispatch_pending(backend, NULL);
 	} else if (read == -1 && errno != EAGAIN) {
+		log_errorf("Could not read from connection: %s", strerror(errno));
 		return -1;
 	}
 
@@ -301,32 +307,34 @@ static struct libseat *_open_seat(struct libseat_seat_listener *listener, void *
 
 	size_t size = read_header(&backend->connection, SERVER_SEAT_OPENED);
 	if (size == SIZE_MAX) {
-		check_error(&backend->connection);
 		destroy(backend);
 		return NULL;
 	}
 
 	struct proto_server_seat_opened rmsg;
 	if (sizeof rmsg > size) {
-		errno = EBADMSG;
-		return NULL;
+		goto badmsg_error;
 	}
 
 	if (connection_get(&backend->connection, &rmsg, sizeof rmsg) == -1) {
-		return NULL;
+		goto badmsg_error;
 	};
 
 	if (sizeof rmsg + rmsg.seat_name_len > size ||
 	    rmsg.seat_name_len >= sizeof backend->seat_name) {
-		errno = EBADMSG;
-		return NULL;
+		goto badmsg_error;
 	}
 
 	if (connection_get(&backend->connection, backend->seat_name, rmsg.seat_name_len) == -1) {
-		return NULL;
+		goto badmsg_error;
 	};
 
 	return &backend->base;
+
+badmsg_error:
+	log_error("Received invalid message");
+	errno = EBADMSG;
+	return NULL;
 }
 
 static struct libseat *open_seat(struct libseat_seat_listener *listener, void *data) {
@@ -354,7 +362,6 @@ static int close_seat(struct libseat *base) {
 
 	size_t size = read_header(&backend->connection, SERVER_SEAT_CLOSED);
 	if (size == SIZE_MAX) {
-		check_error(&backend->connection);
 		destroy(backend);
 		return -1;
 	}
@@ -393,26 +400,29 @@ static int open_device(struct libseat *base, const char *path, int *fd) {
 
 	size_t size = read_header(&backend->connection, SERVER_DEVICE_OPENED);
 	if (size == SIZE_MAX) {
-		check_error(&backend->connection);
 		return -1;
 	}
 
 	struct proto_server_device_opened rmsg;
 	if (sizeof rmsg > size) {
-		errno = EBADMSG;
-		return -1;
+		goto badmsg_error;
 	}
 	if (connection_get(&backend->connection, &rmsg, sizeof rmsg) == -1) {
-		return -1;
+		goto badmsg_error;
 	}
 
 	int received_fd = connection_get_fd(&backend->connection);
 	if (received_fd == -1) {
-		return -1;
+		goto badmsg_error;
 	}
 
 	*fd = received_fd;
 	return rmsg.device_id;
+
+badmsg_error:
+	log_error("Received invalid message");
+	errno = EBADMSG;
+	return -1;
 }
 
 static int close_device(struct libseat *base, int device_id) {
@@ -437,24 +447,26 @@ static int close_device(struct libseat *base, int device_id) {
 
 	size_t size = read_header(&backend->connection, SERVER_DEVICE_CLOSED);
 	if (size == SIZE_MAX) {
-		check_error(&backend->connection);
 		return -1;
 	}
 
 	struct proto_server_device_closed rmsg;
 	if (sizeof rmsg > size) {
-		errno = EBADMSG;
-		return -1;
+		goto badmsg_error;
 	}
 	if (connection_get(&backend->connection, &rmsg, sizeof rmsg) == -1) {
-		return -1;
+		goto badmsg_error;
 	}
 	if (rmsg.device_id != device_id) {
-		errno = EBADMSG;
-		return -1;
+		goto badmsg_error;
 	}
 
 	return 0;
+
+badmsg_error:
+	log_error("Received invalid message");
+	errno = EBADMSG;
+	return -1;
 }
 
 static int switch_session(struct libseat *base, int session) {
@@ -531,11 +543,13 @@ static int set_deathsig(int signal) {
 static struct libseat *builtin_open_seat(struct libseat_seat_listener *listener, void *data) {
 	int fds[2];
 	if (socketpair(AF_UNIX, SOCK_STREAM, 0, fds) == -1) {
+		log_errorf("Could not create socket pair: %s", strerror(errno));
 		return NULL;
 	}
 
 	pid_t pid = fork();
 	if (pid == -1) {
+		log_errorf("Could not fork: %s", strerror(errno));
 		close(fds[0]);
 		close(fds[1]);
 		return NULL;
@@ -544,16 +558,20 @@ static struct libseat *builtin_open_seat(struct libseat_seat_listener *listener,
 		int res = 0;
 		struct server server = {0};
 		if (server_init(&server) == -1) {
+			log_errorf("Could not init embedded seatd server: %s", strerror(errno));
 			res = 1;
 			goto error;
 		}
 		if (server_add_client(&server, fd) == -1) {
+			log_errorf("Could not add client to embedded seatd server: %s",
+				   strerror(errno));
 			res = 1;
 			goto server_error;
 		}
 		set_deathsig(SIGTERM);
 		while (server.running) {
 			if (poller_poll(&server.poller) == -1) {
+				log_errorf("Could not poll server socket: %s", strerror(errno));
 				res = 1;
 				goto server_error;
 			}