From d5e66d8f51e41841356b9b268e8a4a9ec4b7828f Mon Sep 17 00:00:00 2001 From: Tom Smeding Date: Thu, 9 Jul 2020 23:14:18 +0200 Subject: ssh server: Less noise --- ssh/server.c | 97 ++++++++++++++++++++++++++++++++++-------------------------- 1 file 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 #include +#include #include #include #include @@ -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)); -- cgit v1.2.3-54-g00ecf