ssh server: Less noise

1 files changed, 55 insertions, 42 deletions

diff --git a/ssh/server.c b/ssh/server.c
index 96fc09e..84f0587 100644
--- a/ssh/server.c
+++ b/ssh/server.c
@@ -1,5 +1,6 @@
 #include <stdio.h>
 #include <stdlib.h>
+#include <stdarg.h>
 #include <stdbool.h>
 #include <stdatomic.h>
 #include <string.h>
@@ -20,6 +21,18 @@
 
 #define RESOURCE_ERROR_SLEEP_MS 10000
 
+static const bool debug_enabled = false;
+
+
+__attribute__((format (printf, 1, 2)))
+static void debug(const char *restrict format, ...) {
+	if (debug_enabled) {
+		va_list ap;
+		va_start(ap, format);
+		vfprintf(stderr, format, ap);
+		va_end(ap);
+	}
+}
 
 static void xxd(FILE *stream, const void *buf_, size_t length) {
 	unsigned char *buf = (unsigned char*)buf_;
@@ -70,10 +83,10 @@ static int channel_subsystem_request_cb(ssh_session session, ssh_channel channel
 	(void)channel;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
 	if (strcmp(subsystem, "tomsg") == 0) {
-		printf("[%d] subsystem request: <%s>, allowing\n", tdata->thread_id, subsystem);
+		debug("[%d] subsystem request: <%s>, allowing\n", tdata->thread_id, subsystem);
 		return 0;
 	} else {
-		printf("[%d] subsystem request: <%s>, denying!\n", tdata->thread_id, subsystem);
+		debug("[%d] subsystem request: <%s>, denying!\n", tdata->thread_id, subsystem);
 		return 1;
 	}
 }
@@ -81,51 +94,50 @@ static int channel_subsystem_request_cb(ssh_session session, ssh_channel channel
 static void channel_close_cb(ssh_session session, ssh_channel channel, void *tdata_) {
 	(void)session; (void)channel;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
-	printf("[%d] channel close!\n", tdata->thread_id);
+	debug("[%d] channel close!\n", tdata->thread_id);
 }
 
 static void channel_eof_cb(ssh_session session, ssh_channel channel, void *tdata_) {
 	(void)session; (void)channel;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
-	printf("[%d] eof on channel, setting close flag\n", tdata->thread_id);
+	debug("[%d] eof on channel, setting close flag\n", tdata->thread_id);
 	tdata->should_close = true;
 }
 
 static int channel_data_cb(ssh_session session, ssh_channel channel, void *data, uint32_t len, int is_stderr, void *tdata_) {
 	(void)is_stderr; (void)data; (void)channel; (void)session;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
-	printf("[%d] data on channel (length %u):\n", tdata->thread_id, len);
-	xxd(stdout, data, len);
-	// printf("[%d] echoing back!\n", tdata->thread_id);
+
+	debug("[%d] data on channel (length %u):\n", tdata->thread_id, len);
+	if (debug_enabled) xxd(stdout, data, len);
+
+	// debug("[%d] echoing back!\n", tdata->thread_id);
 	// if (ssh_channel_write(channel, data, len) == SSH_ERROR) {
-	//     printf("[%d] write to channel failed! Setting close flag\n", tdata->thread_id);
+	//     debug("[%d] write to channel failed! Setting close flag\n", tdata->thread_id);
 	//     tdata->should_close = true;
 	// }
+
 	const char *start = (const char*)data;
 	const char *cursor = start;
 	const char *end = start + len;
+
 	while (cursor < end) {
 		ssize_t nw = write(tdata->backend_fd, cursor, end - cursor);
 		if (nw < 0) {
 			if (errno == EINTR) continue;
-			printf("[%d] error writing to backend socket: %s\n", tdata->thread_id, strerror(errno));
+			debug("[%d] error writing to backend socket: %s\n", tdata->thread_id, strerror(errno));
 			tdata->should_close = true;
 			return cursor - start;
 		}
 		if (nw == 0) {  // should not happen?
-			printf("[%d] write(2) returned 0?\n", tdata->thread_id);
+			debug("[%d] write(2) returned 0?\n", tdata->thread_id);
 			tdata->should_close = true;
 			return cursor - start;
 		}
 		cursor += nw;
 	}
-	return len;
-}
 
-static int channel_write_wontblock_cb(ssh_session session, ssh_channel channel, size_t bytes, void *tdata_) {
-	(void)channel; (void)session;
-	printf("[%d] write won't block for %zu bytes notification\n", ((struct thread_data*)tdata_)->thread_id, bytes);
-	return 0;
+	return len;
 }
 
 ////////// SERVER CALLBACKS //////////
@@ -133,7 +145,7 @@ static int channel_write_wontblock_cb(ssh_session session, ssh_channel channel,
 static int auth_none_cb(ssh_session session, const char *user, void *tdata_) {
 	(void)session;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
-	printf("[%d] auth none (user <%s>), accepting\n", tdata->thread_id, user);
+	debug("[%d] auth none (user <%s>), accepting\n", tdata->thread_id, user);
 	return SSH_AUTH_SUCCESS;
 }
 
@@ -141,10 +153,10 @@ static int service_request_cb(ssh_session session, const char *service, void *td
 	(void)session;
 	struct thread_data *tdata = (struct thread_data*)tdata_;
 	if (strcmp(service, "ssh-userauth") == 0) {
-		printf("[%d] ssh-userauth service request, allowing through\n", tdata->thread_id);
+		debug("[%d] ssh-userauth service request, allowing through\n", tdata->thread_id);
 		return 0;
 	} else {
-		printf("[%d] service request <%s>, not allowing\n", tdata->thread_id, service);
+		debug("[%d] service request <%s>, not allowing\n", tdata->thread_id, service);
 		return -1;
 	}
 }
@@ -155,7 +167,7 @@ static ssh_channel chan_open_request_cb(ssh_session session, void *tdata_) {
 		ssh_channel chan = ssh_channel_new(session);
 		if (chan != NULL) {
 			if (ssh_set_channel_callbacks(chan, &tdata->chan_cb) == SSH_OK) {
-				printf("[%d] channel open request, allowing\n", tdata->thread_id);
+				debug("[%d] channel open request, allowing\n", tdata->thread_id);
 				tdata->channel = chan;
 				return chan;
 			}
@@ -163,7 +175,7 @@ static ssh_channel chan_open_request_cb(ssh_session session, void *tdata_) {
 			ssh_channel_free(chan);
 		}
 	}
-	printf("[%d] channel open request, denying!\n", tdata->thread_id);
+	debug("[%d] channel open request, denying!\n", tdata->thread_id);
 	return NULL;
 }
 
@@ -171,6 +183,7 @@ static int backend_data_cb(int fd, int revents, void *tdata_) {
 	struct thread_data *tdata = (struct thread_data*)tdata_;
 
 	if (revents & (POLLERR|POLLHUP|POLLNVAL)) {
+		// Print this always, because backend issues are interesting
 		char descr[64] = "";
 		if (revents & POLLERR) strcat(descr, "|POLLERR");
 		if (revents & POLLHUP) strcat(descr, "|POLLHUP");
@@ -185,6 +198,7 @@ static int backend_data_cb(int fd, int revents, void *tdata_) {
 		ssize_t nr = read(fd, buffer, sizeof buffer);
 		if (nr < 0) {
 			if (errno == EINTR) return 0;
+			// Backend issues are interesting, not noise
 			printf("[%d] Error reading from backend socket: %s\n", tdata->thread_id, strerror(errno));
 			tdata->should_close = true;
 			return 0;
@@ -199,7 +213,7 @@ static int backend_data_cb(int fd, int revents, void *tdata_) {
 		while (cursor < nr) {
 			int nw = ssh_channel_write(tdata->channel, buffer + cursor, nr - cursor);
 			if (nw == SSH_ERROR) {
-				printf("[%d] Error writing to ssh channel: %s\n", tdata->thread_id, ssh_get_error(tdata->channel));
+				debug("[%d] Error writing to ssh channel: %s\n", tdata->thread_id, ssh_get_error(tdata->channel));
 				tdata->should_close = true;
 				return 0;
 			}
@@ -266,13 +280,13 @@ static bool lookup_backend(const char *host, int port, struct addrinfo *dst) {
 	int last_failure = 0;
 	bool success = false;
 	for (struct addrinfo *item = result; item; ) {
-		printf("lookup_backend: option ");
-		print_addrinfo(stdout, item);
+		debug("lookup_backend: option ");
+		if (debug_enabled) print_addrinfo(stdout, item);
 
 		int sock = socket(item->ai_family, item->ai_socktype, item->ai_protocol);
 		if (sock == -1) {
 			last_failure = errno;
-			printf("  socket() failure: %s\n", strerror(last_failure));
+			debug("  socket() failure: %s\n", strerror(last_failure));
 			continue;
 		}
 
@@ -281,7 +295,7 @@ static bool lookup_backend(const char *host, int port, struct addrinfo *dst) {
 		close(sock);
 
 		if (ret == 0) {
-			printf("  success!\n");
+			debug("  success!\n");
 			success = true;
 			// Free the rest of the linked list, keeping this item intact.
 			freeaddrinfo(item->ai_next);
@@ -289,10 +303,10 @@ static bool lookup_backend(const char *host, int port, struct addrinfo *dst) {
 			dst->ai_next = NULL;
 			break;
 		} else {
-			printf("  connect() failure: %s\n", strerror(last_failure));
+			debug("  connect() failure: %s\n", strerror(last_failure));
 		}
 
-		printf("  next=%p\n", item->ai_next);
+		debug("  next=%p\n", item->ai_next);
 
 		// Free this element in the linked list, but preserve (and switch to) the tail.
 		struct addrinfo *next = item->ai_next;
@@ -315,7 +329,7 @@ static int connect_backend(const struct thread_data *tdata) {
 	if (sock == -1) return -1;
 
 	if (connect(sock, item->ai_addr, item->ai_addrlen) == 0) {
-		printf("connect_backend: sock=%d\n", sock);
+		debug("connect_backend: sock=%d\n", sock);
 		return sock;
 	}
 
@@ -329,7 +343,7 @@ static void* thread_entry(void *tdata_) {
 	const ssh_session session = tdata->session;
 	ssh_event event = NULL;
 
-	printf("[%d] Thread started\n", tid);
+	debug("[%d] Thread started\n", tid);
 
 	memset(&tdata->server_cb, 0, sizeof tdata->server_cb);
 	ssh_callbacks_init(&tdata->server_cb);
@@ -345,34 +359,33 @@ static void* thread_entry(void *tdata_) {
 	tdata->chan_cb.channel_close_function = channel_close_cb;
 	tdata->chan_cb.channel_eof_function = channel_eof_cb;
 	tdata->chan_cb.channel_data_function = channel_data_cb;
-	tdata->chan_cb.channel_write_wontblock_function = channel_write_wontblock_cb;
 
 	if (ssh_set_server_callbacks(session, &tdata->server_cb) != SSH_OK) {
-		printf("[%d] Failed setting server callbacks: %s\n", tid, ssh_get_error(session));
+		debug("[%d] Failed setting server callbacks: %s\n", tid, ssh_get_error(session));
 		goto cleanup;
 	}
 
 	ssh_set_auth_methods(session, SSH_AUTH_METHOD_NONE);
 
 	if (ssh_handle_key_exchange(session) != SSH_OK) {
-		printf("[%d] Key exchange failed: %s\n", tid, ssh_get_error(session));
+		debug("[%d] Key exchange failed: %s\n", tid, ssh_get_error(session));
 		goto cleanup;
 	}
-	printf("[%d] Handled key exchange\n", tid);
+	debug("[%d] Handled key exchange\n", tid);
 
 	tdata->backend_fd = connect_backend(tdata);
 	if (tdata->backend_fd == -1) {
-		printf("[%d] Failed to connect to backend: %s\n", tid, strerror(errno));
+		debug("[%d] Failed to connect to backend: %s\n", tid, strerror(errno));
 		goto cleanup;
 	}
 
-	printf("[%d] Connected to backend (fd=%d)\n", tid, tdata->backend_fd);
+	debug("[%d] Connected to backend (fd=%d)\n", tid, tdata->backend_fd);
 
 	event = ssh_event_new();
 	if (!event
 			|| ssh_event_add_session(event, session) != SSH_OK
 			|| ssh_event_add_fd(event, tdata->backend_fd, POLLIN, backend_data_cb, tdata) != SSH_OK) {
-		printf("[%d] Failed to create ssh event context\n", tid);
+		debug("[%d] Failed to create ssh event context\n", tid);
 		goto cleanup;
 	}
 
@@ -382,7 +395,7 @@ static void* thread_entry(void *tdata_) {
 		int status = ssh_get_status(session);
 		if (status & (SSH_CLOSED | SSH_CLOSED_ERROR)) goto cleanup;
 		if (status & SSH_READ_PENDING) {
-			printf("[%d] read pending?\n", tid);
+			debug("[%d] read pending?\n", tid);
 		}
 	}
 
@@ -396,12 +409,12 @@ cleanup:
 	if (session) {
 		ssh_disconnect(session);
 		ssh_free(session);
-		printf("[%d] Disconnected\n", tid);
+		debug("[%d] Disconnected\n", tid);
 	}
 	free(tdata);
 	int num_threads = atomic_fetch_sub(&g_thread_count, 1);
-	printf("[%d] Exiting! (%d threads remaining)\n", tid, num_threads - 1);
-	pthread_exit(NULL);
+	debug("[%d] Exiting! (%d threads remaining)\n", tid, num_threads - 1);
+	return NULL;
 }
 
 static void generate_key(const char *outfile) {
@@ -549,7 +562,7 @@ int main(int argc, char **argv) {
 		}
 
 		int num_existing_threads = atomic_fetch_add(&g_thread_count, 1);
-		printf("Accepted connection, spinning up thread (currently %d threads)\n",
+		debug("Accepted connection, spinning up thread (currently %d threads)\n",
 				num_existing_threads + 1);
 
 		struct thread_data *tdata = calloc(1, sizeof(struct thread_data));