From fe91be997df1bba472f7bcc9d8d2efd1271c25cf Mon Sep 17 00:00:00 2001 From: David Sheets Date: Fri, 15 Apr 2016 17:11:38 +0100 Subject: [PATCH] transfused: push log messages over control channel if available Also, remove self-logging and triggers. Signed-off-by: David Sheets --- .../packages/transfused/etc/init.d/transfused | 4 +- alpine/packages/transfused/transfused.c | 255 ++++++++---------- alpine/packages/transfused/transfused.h | 10 +- alpine/packages/transfused/transfused_log.c | 172 ++++++++---- alpine/packages/transfused/transfused_log.h | 18 +- alpine/packages/transfused/transfused_vsock.c | 14 +- 6 files changed, 259 insertions(+), 214 deletions(-) diff --git a/alpine/packages/transfused/etc/init.d/transfused b/alpine/packages/transfused/etc/init.d/transfused index 7e915b051..551236803 100755 --- a/alpine/packages/transfused/etc/init.d/transfused +++ b/alpine/packages/transfused/etc/init.d/transfused @@ -27,9 +27,7 @@ start() --pidfile ${PIDFILE} \ -- \ -p "${PIDFILE}" \ - -l "${STARTUP_LOGFILE}" \ - -m "${MOUNT_TRIGGER}" \ - -t "${RUNTIME_LOGFILE}" + -l "${STARTUP_LOGFILE}" eend $? "Failed to start transfused" } diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 68ada7316..d6e26c059 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -44,22 +44,20 @@ char * default_socket = DEFAULT_SOCKET; char * default_server = DEFAULT_SERVER; char * usage = "usage: transfused [-p pidfile] [-d server] [-s socket] [-f fusermount]\n" - " [-l logfile] [-m mount_trigger] [-t triggerlog]\n" + " [-l logfile]\n" " -p pidfile\tthe path at which to write the pid of the process\n" " -d " DEFAULT_SERVER "\tthe server address to use ('v:addr:port')\n" " -s " DEFAULT_SOCKET "\tthe socket address to use ('v:addr:port')\n" " -f " DEFAULT_FUSERMOUNT "\tthe fusermount executable to use\n" - " -l logfile\tthe log file to use before the mount trigger\n" - " -m mount_trigger\tthe mountpoint to use to trigger log switchover\n" - " -t triggerlog\tthe file to use after the trigger\n"; + " -l logfile\tthe log file to use before uplink\n" + ; int debug = 0; pthread_attr_t detached; typedef struct { - char * descr; - char * tag; + connection_t * connection; int from; int to; } copy_thread_state; @@ -74,7 +72,7 @@ void * must_malloc(char *const descr, size_t size) { void * ptr; ptr = malloc(size); - if (size != 0 && ptr == NULL) die(1, descr, ""); + if (size != 0 && ptr == NULL) die(1, NULL, descr, ""); return ptr; } @@ -82,39 +80,40 @@ void * must_malloc(char *const descr, size_t size) { void cond_init(char *const descr, pthread_cond_t * cond, const pthread_condattr_t *restrict attr) { if ((errno = pthread_cond_init(cond, attr))) - die(1, "", "cond init %s: ", descr); + die(1, NULL, "", "cond init %s: ", descr); } void lock_init(char *const descr, pthread_mutex_t * mutex, const pthread_mutexattr_t *restrict attr) { if ((errno = pthread_mutex_init(mutex, attr))) - die(1, "", "lock init %s: ", descr); + die(1, NULL, "", "lock init %s: ", descr); } void lock(char *const descr, pthread_mutex_t * mutex) { if ((errno = pthread_mutex_lock(mutex))) - die(1, "", "lock %s: ", descr); + die(1, NULL, "", "lock %s: ", descr); } void unlock(char *const descr, pthread_mutex_t * mutex) { if ((errno = pthread_mutex_unlock(mutex))) - die(1, "", "unlock %s: ", descr); + die(1, NULL, "", "unlock %s: ", descr); } int bind_socket(const char * socket) { int sock; if (socket[0] == 0) - die(2, NULL, "Socket family required"); + die(2, NULL, NULL, "Socket family required"); + if (socket[1] != ':') - die(2, NULL, "Socket address required"); + die(2, NULL, NULL, "Socket address required"); switch (socket[0]) { case 'v': sock = bind_vsock(socket + 2); break; default: - die(2, NULL, "Unknown socket family '%c'", socket[0]); + die(2, NULL, NULL, "Unknown socket family '%c'", socket[0]); } return sock; @@ -124,30 +123,30 @@ int connect_socket(const char * socket) { int sock; if (socket[0] == 0) - die(2, NULL, "Socket family required"); + die(2, NULL, NULL, "Socket family required"); if (socket[1] != ':') - die(2, NULL, "Scoket address required"); + die(2, NULL, NULL, "Scoket address required"); switch (socket[0]) { case 'v': sock = connect_vsock(socket + 2); break; default: - die(2, NULL, "Unknown socket family '%c'", socket[0]); + die(2, NULL, NULL, "Unknown socket family '%c'", socket[0]); } return sock; } -char ** read_opts(connection_t * connection, char * buf) { +char ** read_opts(connection_t * conn, char * buf) { int read_count; int optc = 1; char ** optv; size_t mount_len; // TODO: deal with socket read conditions e.g. EAGAIN - read_count = read(connection->sock, buf, EVENT_BUFSZ - 1); - if (read_count < 0) die(1, "read_opts error reading", ""); + read_count = read(conn->sock, buf, EVENT_BUFSZ - 1); + if (read_count < 0) die(1, conn->params, "read_opts error reading", ""); // TODO: protocol should deal with short read buf[read_count] = 0x0; @@ -169,9 +168,9 @@ char ** read_opts(connection_t * connection, char * buf) { } mount_len = strnlen(optv[optc - 1], 4096) + 1; - connection->mount_point = must_malloc("mount point string", mount_len); - strncpy(connection->mount_point, optv[optc - 1], mount_len - 1); - connection->mount_point[mount_len - 1] = '\0'; + conn->mount_point = must_malloc("mount point string", mount_len); + strncpy(conn->mount_point, optv[optc - 1], mount_len - 1); + conn->mount_point[mount_len - 1] = '\0'; return optv; } @@ -180,7 +179,9 @@ uint64_t message_id(uint64_t * message) { return message[1]; } -int read_message(char * descr, int fd, char * buf, size_t max_read) { +int read_message +(char * descr, parameters * params, int fd, char * buf, size_t max_read) +{ int read_count; size_t nbyte; uint32_t len; @@ -188,13 +189,15 @@ int read_message(char * descr, int fd, char * buf, size_t max_read) { // TODO: socket read conditions e.g. EAGAIN read_count = read(fd, buf, 4); if (read_count != 4) { - if (read_count < 0) die(1, "", "read %s: error reading: ", descr); - if (read_count == 0) die(1, NULL, "read %s: EOF reading length", descr); - die(1, NULL, "read %s: short read length %d", descr, read_count); + if (read_count < 0) + die(1, params, "", "read %s: error reading: ", descr); + if (read_count == 0) + die(1, params, NULL, "read %s: EOF reading length", descr); + die(1, params, NULL, "read %s: short read length %d", descr, read_count); } len = *((uint32_t *) buf); if (len > max_read) - die(1, NULL, "read %s: message size %d exceeds buffer capacity %d", + die(1, params, NULL, "read %s: message size %d exceeds buffer capacity %d", len, max_read); nbyte = (size_t) (len - 4); @@ -203,8 +206,8 @@ int read_message(char * descr, int fd, char * buf, size_t max_read) { do { // TODO: socket read conditions e.g. EAGAIN read_count = read(fd, buf, nbyte); - if (read_count < 0) die(1, "", "read %s: error reading: ", descr); - if (read_count == 0) die(1, NULL, "read %s: EOF reading", descr); + if (read_count < 0) die(1, params, "", "read %s: error reading: ", descr); + if (read_count == 0) die(1, params, NULL, "read %s: EOF reading", descr); nbyte -= read_count; buf += read_count; } while (nbyte != 0); @@ -215,35 +218,37 @@ int read_message(char * descr, int fd, char * buf, size_t max_read) { void copy_into_fuse(copy_thread_state * copy_state) { int from = copy_state->from; int to = copy_state->to; - char * descr = copy_state->descr; + char * descr = copy_state->connection->mount_point; int read_count, write_count; void * buf; + parameters * params = copy_state->connection->params; buf = must_malloc(descr, IN_BUFSZ); while(1) { - read_count = read_message(descr, from, (char *) buf, IN_BUFSZ); + read_count = read_message(descr, params, from, (char *) buf, IN_BUFSZ); write_count = write(to, buf, read_count); - if (write_count < 0) die(1, "", "copy %s: error writing: ", descr); + if (write_count < 0) die(1, params, "", "copy %s: error writing: ", descr); // /dev/fuse accepts only complete writes if (write_count != read_count) - die(1, NULL, "copy %s: read %d but only wrote %d", + die(1, params, NULL, "copy %s: read %d but only wrote %d", descr, read_count, write_count); } free(buf); } -void write_exactly(char * descr, int fd, char * buf, size_t nbyte) { +void write_exactly(char * descr, int fd, void * p, size_t nbyte) { int write_count; + char * buf = p; do { // TODO: socket write conditions e.g. EAGAIN write_count = write(fd, buf, nbyte); - if (write_count < 0) die(1, "", "copy %s: error writing: ", descr); - if (write_count == 0) die(1, "", "copy %s: 0 write: ", descr); + if (write_count < 0) die(1, NULL, "", "%s: error writing: ", descr); + if (write_count == 0) die(1, NULL, "", "%s: 0 write: ", descr); nbyte -= write_count; buf += write_count; @@ -253,16 +258,17 @@ void write_exactly(char * descr, int fd, char * buf, size_t nbyte) { void copy_outof_fuse(copy_thread_state * copy_state) { int from = copy_state->from; int to = copy_state->to; - char * descr = copy_state->descr; + char * descr = copy_state->connection->mount_point; int read_count; void * buf; + parameters * params = copy_state->connection->params; buf = must_malloc(descr, OUT_BUFSZ); while(1) { // /dev/fuse only returns complete reads read_count = read(from, buf, OUT_BUFSZ); - if (read_count < 0) die(1, "", "copy %s: error reading: ", descr); + if (read_count < 0) die(1, params, "", "copy %s: error reading: ", descr); write_exactly(descr, to, (char *) buf, read_count); } @@ -275,7 +281,6 @@ void * copy_clean_into_fuse(copy_thread_state * copy_state) { close(copy_state->from); - free(copy_state->descr); free(copy_state); return NULL; @@ -290,7 +295,6 @@ void * copy_clean_outof_fuse(copy_thread_state * copy_state) { close(copy_state->to); - free(copy_state->descr); free(copy_state); return NULL; @@ -300,7 +304,7 @@ void * copy_clean_outof_fuse_thread(void * copy_state) { return (copy_clean_outof_fuse((copy_thread_state *) copy_state)); } -int recv_fd(int sock) { +int recv_fd(parameters * params, int sock) { int ret; int fd = -1; char iochar; @@ -323,7 +327,7 @@ int recv_fd(int sock) { ret = recvmsg(sock, &msg, 0); - if (ret == -1) die(1, "recvmsg", ""); + if (ret == -1) die(1, params, "recvmsg", ""); if (ret > 0 && msg.msg_controllen > 0) { cmsg = CMSG_FIRSTHDR(&msg); @@ -350,19 +354,20 @@ int get_fuse_sock(connection_t * conn, int optc, char *const optv[]) { argv[0] = conn->params->fusermount; memcpy(&argv[1], optv, (optc + 1) * sizeof(char *)); - lock("get_fuse_sock fd_lock", &conn->params->fd_lock); - log_time_locked(conn,"mount "); - for (int i = 0; argv[i]; i++) log_continue_locked(conn, "%s ",argv[i]); - log_continue_locked(conn, "\n"); - unlock("get_fuse_sock fd_lock", &conn->params->fd_lock); + lock("get_fuse_sock ctl_lock", &conn->params->ctl_lock); + log_time_locked(conn->params, "mount "); + for (int i = 0; argv[i]; i++) + log_continue_locked(conn->params, "%s ",argv[i]); + log_continue_locked(conn->params, "\n"); + unlock("get_fuse_sock ctl_lock", &conn->params->ctl_lock); // make the socket over which we'll be sent the FUSE socket fd if (socketpair(PF_UNIX, SOCK_STREAM, 0, fuse_socks)) - die(1, "Couldn't create FUSE socketpair", ""); + die(1, conn->params, "Couldn't create FUSE socketpair", ""); // prepare to exec the suid binary fusermount if (asprintf(&envp[0], "_FUSE_COMMFD=%d", fuse_socks[0]) == -1) - die(1, "Couldn't allocate fusermount envp", ""); + die(1, conn->params, "Couldn't allocate fusermount envp", ""); envp[1] = 0x0; @@ -370,7 +375,7 @@ int get_fuse_sock(connection_t * conn, int optc, char *const optv[]) { fusermount_pid = fork(); if (!fusermount_pid) // child if (execve(argv[0], argv, envp)) - die(1, "Failed to execute fusermount", ""); + die(1, conn->params, "Failed to execute fusermount", ""); // parent free(argv); @@ -382,16 +387,17 @@ int get_fuse_sock(connection_t * conn, int optc, char *const optv[]) { // wait for fusermount to return waitpid(fusermount_pid, &status, 0); if (!WIFEXITED(status)) - die(1, NULL, "fusermount terminated abnormally"); + die(1, conn->params, NULL, "fusermount terminated abnormally"); if (WEXITSTATUS(status)) - die(1, NULL, "fusermount exited with code %d", WEXITSTATUS(status)); + die(1, conn->params, NULL, + "fusermount exited with code %d", WEXITSTATUS(status)); - if (debug) log_time(conn, "about to recv_fd from fusermount\n"); + if (debug) log_time(conn->params, "about to recv_fd from fusermount\n"); - fd = recv_fd(fuse_socks[1]); + fd = recv_fd(conn->params, fuse_socks[1]); if (fd == -1) - die(1, NULL, "Couldn't receive fd over FUSE socket"); + die(1, conn->params, NULL, "Couldn't receive fd over FUSE socket"); // close the read end of the socket close(fuse_socks[1]); @@ -405,13 +411,13 @@ void start_reader(connection_t * connection, int fuse) { copy_state = (copy_thread_state *) must_malloc("start_reader copy_state", sizeof(copy_thread_state)); - copy_state->descr = connection->mount_point; - copy_state->tag = "read"; + copy_state->connection = connection; copy_state->from = connection->sock; copy_state->to = fuse; if ((errno = pthread_create(&child, &detached, copy_clean_into_fuse_thread, copy_state))) - die(1, "", "couldn't create read copy thread for mount %s: ", + die(1, connection->params, "", + "couldn't create read copy thread for mount %s: ", connection->mount_point); } @@ -421,13 +427,13 @@ void start_writer(connection_t * connection, int fuse) { copy_state = (copy_thread_state *) must_malloc("do_write copy_state", sizeof(copy_thread_state)); - copy_state->descr = connection->mount_point; - copy_state->tag = "write"; + copy_state->connection = connection; copy_state->from = fuse; copy_state->to = connection->sock; if ((errno = pthread_create(&child, &detached, copy_clean_outof_fuse_thread, copy_state))) - die(1, "", "Couldn't create write copy thread for mount %s: ", + die(1, connection->params, "", + "Couldn't create write copy thread for mount %s: ", connection->mount_point); } @@ -448,6 +454,7 @@ void * mount_connection(connection_t * conn) { fuse = get_fuse_sock(conn, optc, optv); free(buf); + free(optv); lock_init("copy_lock", ©_lock, NULL); cond_init("copy_halt", ©_halt, NULL); @@ -455,29 +462,11 @@ void * mount_connection(connection_t * conn) { start_reader(conn, fuse); start_writer(conn, fuse); - // trigger? - // TODO: strcmp scares me - // TODO: append logfile to trigger_log - if (conn->params->mount_trigger != NULL - && conn->params->trigger_log != NULL - && 0 == strcmp(optv[optc - 1], conn->params->mount_trigger)) { - - lock("trigger mount fd_lock", &conn->params->fd_lock); - log_time_locked(conn, "Log mount trigger fired on %s, logging to %s\n", - conn->params->mount_trigger, conn->params->trigger_log); - conn->params->trigger_fd = open(conn->params->trigger_log, - O_WRONLY | O_APPEND | O_CREAT, 0600); - if (conn->params->trigger_fd == -1) - die(1, "", "Couldn't open trigger log %s: ", conn->params->trigger_log); - unlock("trigger mount fd_lock", &conn->params->fd_lock); - } - - free(optv); - lock("copy lock", ©_lock); while (!should_halt) if ((errno = pthread_cond_wait(©_halt, ©_lock))) - die(1, "", "Couldn't wait for copy halt for mount %s: ", + die(1, conn->params, "", + "Couldn't wait for copy halt for mount %s: ", conn->mount_point); unlock("copy lock", ©_lock); @@ -496,18 +485,19 @@ void write_pid(connection_t * connection) { int pid_s_len, write_count; if (asprintf(&pid_s, "%lld", (long long) pid) == -1) - die(1, "Couldn't allocate pid string", ""); + die(1, connection->params, "Couldn't allocate pid string", ""); pid_s_len = strlen(pid_s); // TODO: check for socket write conditions e.g. EAGAIN write_count = write(connection->sock, pid_s, pid_s_len); if (write_count < 0) - die(1, "Error writing pid", ""); + die(1, connection->params, "Error writing pid", ""); // TODO: handle short writes if (write_count != pid_s_len) - die(1, NULL, "Error writing pid %s to socket: only wrote %d bytes", + die(1, connection->params, NULL, + "Error writing pid %s to socket: only wrote %d bytes", pid_s, write_count); free(pid_s); @@ -550,7 +540,7 @@ void perform_syscall(connection_t * conn, uint8_t syscall, char path[]) { break; default: - die(1, NULL, "Unknown event syscall %" PRIu8, syscall); + die(1, conn->params, NULL, "Unknown event syscall %" PRIu8, syscall); } if (r != 0) @@ -575,7 +565,8 @@ void * event_thread(void * connection_ptr) { buf = must_malloc("incoming event buffer", EVENT_BUFSZ); while(1) { - read_count = read_message("events", connection->sock, buf, EVENT_BUFSZ); + read_count = read_message("events", connection->params, + connection->sock, buf, EVENT_BUFSZ); if (debug) thread_log_time(connection, "read %d bytes from event connection\n", @@ -596,28 +587,29 @@ void * event_thread(void * connection_ptr) { return NULL; } -void write_pidfile(char * pidfile) { +void write_pidfile(parameters * params) { int fd; pid_t pid = getpid(); char * pid_s; int pid_s_len, write_count; if (asprintf(&pid_s, "%lld", (long long) pid) == -1) - die(1, "Couldn't allocate pidfile string", ""); + die(1, params, "Couldn't allocate pidfile string", ""); pid_s_len = strlen(pid_s); - fd = open(pidfile, O_WRONLY | O_CREAT | O_TRUNC, 0644); + fd = open(params->pidfile, O_WRONLY | O_CREAT | O_TRUNC, 0644); if (fd == -1) - die(1, "", "Couldn't open pidfile path %s: ", pidfile); + die(1, params, "", "Couldn't open pidfile path %s: ", params->pidfile); write_count = write(fd, pid_s, pid_s_len); if (write_count == -1) - die(1, "", "Error writing pidfile %s: ", pidfile); + die(1, params, "", "Error writing pidfile %s: ", params->pidfile); if (write_count != pid_s_len) - die(1, NULL, "Error writing %s to pidfile %s: only wrote %d bytes", - pid_s, pidfile, write_count); + die(1, params, NULL, + "Error writing %s to pidfile %s: only wrote %d bytes", + pid_s, params->pidfile, write_count); close(fd); free(pid_s); @@ -625,31 +617,32 @@ void write_pidfile(char * pidfile) { void * init_thread(void * params_ptr) { parameters * params = params_ptr; - int init_sock = connect_socket(params->server); int write_count, read_count; char init_msg[6] = { '\6', '\0', '\0', '\0', '\0', '\0' }; void * buf; + params->ctl_sock = connect_socket(params->server); + // TODO: handle short write/socket conditions - write_count = write(init_sock, init_msg, sizeof(init_msg)); - if (write_count < 0) die(1, "init thread: couldn't write init", ""); + write_count = write(params->ctl_sock, init_msg, sizeof(init_msg)); + if (write_count < 0) die(1, NULL, "init thread: couldn't write init", ""); if (write_count != sizeof(init_msg)) - die(1, "init thread: incomplete write", ""); + die(1, NULL, "init thread: incomplete write", ""); buf = must_malloc("incoming init buffer", EVENT_BUFSZ); // TODO: handle short read/socket conditions - read_count = read(init_sock, buf, EVENT_BUFSZ); - if (read_count < 0) die(1, "init thread: error reading", ""); + read_count = read(params->ctl_sock, buf, EVENT_BUFSZ); + if (read_count < 0) die(1, params, "init thread: error reading", ""); // TODO: handle other messages - if (read_count != 6) die(1, "init thread: response not 6", ""); + if (read_count != 6) die(1, params, "init thread: response not 6", ""); for (int i = 0; i < sizeof(init_msg); i++) if (((char *)buf)[i] != init_msg[i]) - die(1, "init thread: unexpected message", ""); + die(1, params, "init thread: unexpected message", ""); // we've gotten Continue so write the pidfile if (params->pidfile != NULL) - write_pidfile(params->pidfile); + write_pidfile(params); // TODO: handle more messages return NULL; @@ -661,10 +654,10 @@ void toggle_debug(int sig) { void setup_debug() { if (SIG_ERR == signal(SIGHUP, toggle_debug)) - die(1, "Couldn't set SIGHUP behavior", ""); + die(1, NULL, "Couldn't set SIGHUP behavior", ""); if (siginterrupt(SIGHUP, 1)) - die(1, "Couldn't set siginterrupt for SIGHUP", ""); + die(1, NULL, "Couldn't set siginterrupt for SIGHUP", ""); } void parse_parameters(int argc, char * argv[], parameters * params) { @@ -676,12 +669,11 @@ void parse_parameters(int argc, char * argv[], parameters * params) { params->fusermount = NULL; params->logfile = NULL; params->logfile_fd = 0; - params->mount_trigger = NULL; - params->trigger_log = NULL; - params->trigger_fd = 0; - lock_init("fd_lock", ¶ms->fd_lock, NULL); + params->data_sock = 0; + params->ctl_sock = 0; + lock_init("ctl_lock", ¶ms->ctl_lock, NULL); - while ((c = getopt(argc, argv, ":p:d:s:f:l:m:t:")) != -1) { + while ((c = getopt(argc, argv, ":p:d:s:f:l:")) != -1) { switch(c) { case 'p': @@ -704,14 +696,6 @@ void parse_parameters(int argc, char * argv[], parameters * params) { params->logfile = optarg; break; - case 'm': - params->mount_trigger = optarg; - break; - - case 't': - params->trigger_log = optarg; - break; - case ':': fprintf(stderr, "Option -%c requires a path argument\n", optopt); errflg++; @@ -763,14 +747,6 @@ void parse_parameters(int argc, char * argv[], parameters * params) { perror(""); exit(2); } - - if (params->mount_trigger != NULL - && access(params->mount_trigger, F_OK)) { - fprintf(stderr, "-m %s path to mount point must exist: ", - params->mount_trigger); - perror(""); - exit(2); - } } void serve(parameters * params) { @@ -780,11 +756,11 @@ void serve(parameters * params) { connection_t * conn; void * (*connection_handler_thread)(void *); - if (listen(params->sock, 16)) - die(1, "listen", ""); + if (listen(params->data_sock, 16)) + die(1, NULL, "listen", ""); if ((errno = pthread_create(&child, &detached, init_thread, params))) - die(1, "", "Couldn't create initialization thread: "); + die(1, NULL, "", "Couldn't create initialization thread: "); while (1) { conn = (connection_t *) must_malloc("connection state", @@ -792,14 +768,15 @@ void serve(parameters * params) { conn->params = params; conn->mount_point = ""; - conn->sock = accept(params->sock, &conn->sa_client, &conn->socklen_client); + conn->sock = accept(params->data_sock, + &conn->sa_client, &conn->socklen_client); if (conn->sock < 0) - die(1, "accept", ""); + die(1, params, "accept", ""); // TODO: check for socket read conditions e.g. EAGAIN read_count = read(conn->sock, &subproto_selector, 1); if (read_count <= 0) - die(1, "read subprotocol selector", ""); + die(1, params, "read subprotocol selector", ""); switch (subproto_selector) { case 'm': @@ -811,15 +788,15 @@ void serve(parameters * params) { connection_handler_thread = event_thread; break; default: - die(1, NULL, "Unknown subprotocol type '%c'", subproto_selector); + die(1, params, NULL, "Unknown subprotocol type '%c'", subproto_selector); } if ((errno = pthread_create(&child, &detached, connection_handler_thread, conn))) - die(1, "", "Couldn't create thread for %s connection: ", + die(1, params, "", "Couldn't create thread for %s connection: ", conn->type_descr); - if (debug) log_time(conn, "thread spawned\n"); + if (debug) log_time(conn->params, "thread spawned\n"); } } @@ -830,7 +807,7 @@ int main(int argc, char * argv[]) { core_limit.rlim_cur = RLIM_INFINITY; core_limit.rlim_max = RLIM_INFINITY; if (setrlimit(RLIMIT_CORE, &core_limit)) - die(1, "", "Couldn't set RLIMIT_CORE to RLIM_INFINITY"); + die(1, NULL, "", "Couldn't set RLIMIT_CORE to RLIM_INFINITY"); openlog(argv[0], LOG_CONS | LOG_PERROR | LOG_NDELAY, LOG_DAEMON); @@ -839,15 +816,15 @@ int main(int argc, char * argv[]) { if ((errno = pthread_attr_setdetachstate(&detached, PTHREAD_CREATE_DETACHED))) - die(1, "Couldn't set pthread detach state", ""); + die(1, NULL, "Couldn't set pthread detach state", ""); if (params.logfile != NULL) { params.logfile_fd = open(params.logfile, O_WRONLY | O_APPEND | O_CREAT); if (params.logfile_fd == -1) - die(1, "", "Couldn't open log file %s: ", params.logfile); + die(1, NULL, "", "Couldn't open log file %s: ", params.logfile); } - params.sock = bind_socket(params.socket); + params.data_sock = bind_socket(params.socket); serve(¶ms); return 0; diff --git a/alpine/packages/transfused/transfused.h b/alpine/packages/transfused/transfused.h index 048ae68d7..8a2e64043 100644 --- a/alpine/packages/transfused/transfused.h +++ b/alpine/packages/transfused/transfused.h @@ -7,12 +7,10 @@ typedef struct { char * fusermount; char * pidfile; char * logfile; - char * mount_trigger; - char * trigger_log; - int sock; - pthread_mutex_t fd_lock; int logfile_fd; - int trigger_fd; + int ctl_sock; + int data_sock; + pthread_mutex_t ctl_lock; } parameters; typedef struct { @@ -31,3 +29,5 @@ void * must_malloc(char *const descr, size_t size); void lock(char *const descr, pthread_mutex_t * mutex); void unlock(char *const descr, pthread_mutex_t * mutex); + +void write_exactly(char * descr, int fd, void * buf, size_t nbyte); diff --git a/alpine/packages/transfused/transfused_log.c b/alpine/packages/transfused/transfused_log.c index 1a5cf22fe..f55a487c0 100644 --- a/alpine/packages/transfused/transfused_log.c +++ b/alpine/packages/transfused/transfused_log.c @@ -11,6 +11,7 @@ #include #include #include +#include #include "transfused.h" @@ -34,75 +35,141 @@ void log_timestamp(int fd) { dprintf(fd, "%s.%03d ", timestamp, msec); } -void die(int exit_code, const char * perror_arg, const char * fmt, ...) { - va_list argp; - int in_errno = errno; - va_start(argp, fmt); - vsyslog(LOG_CRIT, fmt, argp); - va_end(argp); - if (perror_arg != NULL) { - if (*perror_arg != 0) - syslog(LOG_CRIT, "%s: %s", perror_arg, strerror(in_errno)); - else - syslog(LOG_CRIT, "%s", strerror(in_errno)); +void die +(int exit_code, parameters * params, const char * parg, const char * fmt, ...); + +void vlog_sock_locked(int fd, const char * fmt, va_list args) { + uint16_t log_err_type = 1; + int rc, len; + va_list targs; + char * fill; + + va_copy(targs, args); + len = vsnprintf(NULL, 0, fmt, targs); + if (len < 0) die(1, NULL, NULL, "Couldn't log due to vsnprintf failure"); + va_end(targs); + + rc = len + 4 + 2; // 4 for length itself and 2 for message type + write_exactly("vlog_sock_locked", fd, (uint32_t *) &rc, sizeof(uint32_t)); + write_exactly("vlog_sock_locked", fd, &log_err_type, sizeof(uint16_t)); + + va_copy(targs, args); + rc = vdprintf(fd, fmt, targs); + if (rc < 0) die(1, NULL, "Couldn't send log message with vdprintf", ""); + va_end(targs); + + if (rc < len) { // we didn't write the whole message :-( + rc = len - rc; + fill = (char *) calloc(rc, 1); + if (fill == NULL) die(1, NULL, "vlog_sock_locked fill", ""); + write_exactly("vlog_sock_locked fill", fd, fill, rc); } - exit(exit_code); } -void vlog_locked(connection_t * conn, const char * fmt, va_list args) { - int fd = conn->params->trigger_fd; - if (fd != 0) { - vdprintf(fd, fmt, args); - } else { - vsyslog(LOG_INFO, fmt, args); - fd = conn->params->logfile_fd; - if (fd != 0) { - vdprintf(fd, fmt, args); - } - } -} - -void vlog_time_locked(connection_t * conn, const char * fmt, va_list args) { - int fd = conn->params->trigger_fd; - if (fd != 0) log_timestamp(fd); - else { - fd = conn->params->logfile_fd; - if (fd != 0) log_timestamp(fd); - } - vlog_locked(conn, fmt, args); -} - -void log_time_locked(connection_t * connection, const char * fmt, ...) { +void log_sock_locked(int fd, const char * fmt, ...) { va_list args; va_start(args, fmt); - vlog_time_locked(connection, fmt, args); + vlog_sock_locked(fd, fmt, args); va_end(args); } -void log_time(connection_t * connection, const char * fmt, ...) { +void die +(int exit_code, parameters * params, const char * parg, const char * fmt, ...) +{ + va_list argp, targs; + int in_errno = errno; + int fd = 0; + + if (params != NULL) { + fd = params->ctl_sock; + lock("die ctl_lock", ¶ms->ctl_lock); + } + + va_start(argp, fmt); + va_copy(targs, argp); + vsyslog(LOG_CRIT, fmt, targs); + va_end(targs); + + if (fd != 0) vlog_sock_locked(fd, fmt, argp); + va_end(argp); + + if (parg != NULL) { + if (*parg != 0) { + syslog(LOG_CRIT, "%s: %s", parg, strerror(in_errno)); + if (fd != 0) log_sock_locked(fd, "%s: %s", parg, strerror(in_errno)); + } else { + syslog(LOG_CRIT, "%s", strerror(in_errno)); + if (fd != 0) log_sock_locked(fd, "%s", strerror(in_errno)); + } + } + + exit(exit_code); + // Nobody else should die before we terminate everything + unlock("die ctl_lock", ¶ms->ctl_lock); +} + +void vlog_locked(parameters * params, const char * fmt, va_list args) { + int rc; + int fd = params->ctl_sock; + va_list targs; + + if (fd != 0) vlog_sock_locked(fd, fmt, args); + else { + va_copy(targs, args); + vsyslog(LOG_INFO, fmt, targs); + va_end(targs); + + fd = params->logfile_fd; + if (fd != 0) { + va_copy(targs, args); + rc = vdprintf(fd, fmt, targs); + if (rc < 0) die(1, NULL, "Couldn't write log message with vdprintf", ""); + va_end(targs); + } + } +} + +void vlog_time_locked(parameters * params, const char * fmt, va_list args) { + int fd = params->logfile_fd; + + if (fd != 0 && params->ctl_sock == 0) log_timestamp(fd); + vlog_locked(params, fmt, args); +} + +void log_time_locked(parameters * params, const char * fmt, ...) { va_list args; va_start(args, fmt); - lock("log_time fd_lock", &connection->params->fd_lock); - vlog_time_locked(connection, fmt, args); - unlock("log_time fd_lock", &connection->params->fd_lock); + vlog_time_locked(params, fmt, args); + + va_end(args); +} + +void log_time(parameters * params, const char * fmt, ...) { + va_list args; + + va_start(args, fmt); + + lock("log_time ctl_lock", ¶ms->ctl_lock); + vlog_time_locked(params, fmt, args); + unlock("log_time ctl_lock", ¶ms->ctl_lock); va_end(args); } typedef struct { - connection_t * connection; + parameters * params; char * msg; } log_thread_state; void * log_time_thread(void * log_state_ptr) { log_thread_state * log_state = log_state_ptr; - log_time(log_state->connection, log_state->msg); + log_time(log_state->params, log_state->msg); free(log_state->msg); free(log_state); @@ -117,11 +184,11 @@ void thread_log_time(connection_t * conn, const char * fmt, ...) { log_state = must_malloc("thread_log_time log_state", sizeof(log_thread_state)); - log_state->connection = conn; + log_state->params = conn->params; va_start(args, fmt); if (vasprintf(&log_state->msg, fmt, args) == -1) - die(1, "Couldn't allocate thread_log_time message", ""); + die(1, conn->params, "Couldn't allocate thread_log_time message", ""); va_end(args); // TODO: We currently spawn a new thread for every message. This is @@ -129,28 +196,29 @@ void thread_log_time(connection_t * conn, const char * fmt, ...) { // log demand to be low. if ((errno = pthread_create(&logger, &detached, log_time_thread, log_state))) - die(1, "", "Couldn't create log thread for %s connection %s: ", + die(1, conn->params, "", + "Couldn't create log thread for %s connection %s: ", conn->type_descr, conn->mount_point); } -void log_continue_locked(connection_t * connection, const char * fmt, ...) { +void log_continue_locked(parameters * params, const char * fmt, ...) { va_list args; va_start(args, fmt); - vlog_locked(connection, fmt, args); + vlog_locked(params, fmt, args); va_end(args); } -void log_continue(connection_t * connection, const char * fmt, ...) { +void log_continue(parameters * params, const char * fmt, ...) { va_list args; va_start(args, fmt); - lock("log_continue fd_lock", &connection->params->fd_lock); - vlog_locked(connection, fmt, args); - unlock("log_continue fd_lock", &connection->params->fd_lock); + lock("log_continue ctl_lock", ¶ms->ctl_lock); + vlog_locked(params, fmt, args); + unlock("log_continue ctl_lock", ¶ms->ctl_lock); va_end(args); } diff --git a/alpine/packages/transfused/transfused_log.h b/alpine/packages/transfused/transfused_log.h index 07fdd0d6e..92801c16d 100644 --- a/alpine/packages/transfused/transfused_log.h +++ b/alpine/packages/transfused/transfused_log.h @@ -2,18 +2,20 @@ #include "transfused.h" -void die(int exit_code, const char * perror_arg, const char * fmt, ...); +void die +(int exit_code, parameters * params, const char * perror_arg, + const char * fmt, ...); -void vlog_locked(connection_t * conn, const char * fmt, va_list args); +void vlog_locked(parameters * params, const char * fmt, va_list args); -void vlog_time_locked(connection_t * conn, const char * fmt, va_list args); +void vlog_time_locked(parameters * params, const char * fmt, va_list args); -void log_time_locked(connection_t * connection, const char * fmt, ...); +void log_time_locked(parameters * params, const char * fmt, ...); -void log_time(connection_t * connection, const char * fmt, ...); +void log_time(parameters * params, const char * fmt, ...); -void thread_log_time(connection_t * connection, const char * fmt, ...); +void thread_log_time(connection_t * conn, const char * fmt, ...); -void log_continue_locked(connection_t * connection, const char * fmt, ...); +void log_continue_locked(parameters * params, const char * fmt, ...); -void log_continue(connection_t * connection, const char * fmt, ...); +void log_continue(parameters * params, const char * fmt, ...); diff --git a/alpine/packages/transfused/transfused_vsock.c b/alpine/packages/transfused/transfused_vsock.c index 25003a6eb..25e0219dd 100644 --- a/alpine/packages/transfused/transfused_vsock.c +++ b/alpine/packages/transfused/transfused_vsock.c @@ -12,7 +12,7 @@ long parse_cid(const char * address) { long cid = strtol(address, &end, 10); if (address == end || *end != ':') { *end = 0; - die(2, NULL, "Invalid vsock cid: %s", address); + die(2, NULL, NULL, "Invalid vsock cid: %s", address); } return cid; } @@ -22,7 +22,7 @@ long parse_port(const char * port_str) { long port = strtol(port_str, &end, 10); if (port_str == end || *end != '\0') { *end = 0; - die(2, NULL, "Invalid vsock port: %s", port_str); + die(2, NULL, NULL, "Invalid vsock port: %s", port_str); } return port; } @@ -35,7 +35,7 @@ int find_colon(const char * address) { else colon++; if (address[colon] == '\0') - die(2, NULL, "Missing port in vsock address %s", address); + die(2, NULL, NULL, "Missing port in vsock address %s", address); return colon; } @@ -62,10 +62,10 @@ int bind_vsock(const char * address) { sock_fd = socket(AF_VSOCK, SOCK_STREAM, 0); if (sock_fd < 0) - die(1, "socket(AF_VSOCK)", ""); + die(1, NULL, "socket(AF_VSOCK)", ""); if (bind(sock_fd, (struct sockaddr *) &sa_listen, sizeof(sa_listen))) - die(1, "bind(AF_VSOCK)", ""); + die(1, NULL, "bind(AF_VSOCK)", ""); return sock_fd; } @@ -90,10 +90,10 @@ int connect_vsock(const char * address) { sock_fd = socket(AF_VSOCK, SOCK_STREAM, 0); if (sock_fd < 0) - die(1, "socket(AF_VSOCK)", ""); + die(1, NULL, "socket(AF_VSOCK)", ""); if (connect(sock_fd, (struct sockaddr *) &sa_connect, sizeof(sa_connect))) - die(1, "connect(AF_VSOCK)", ""); + die(1, NULL, "connect(AF_VSOCK)", ""); return sock_fd; }