From 224bbcea63118f412965e87f5cf5d2eb84f1f5ea Mon Sep 17 00:00:00 2001 From: David Sheets Date: Thu, 17 Mar 2016 10:51:37 +0000 Subject: [PATCH 1/3] transfused: change protocol to support events, add syslog logging The event string in the 9p socket file system now contains a 1 byte channel type immediately preceding the connection ID. This channel type determines which protocol will be used on the channel -- m for FUSE protocol, e for events. The event messages are host-initiated and have the following structure: 2 bytes for total length 2 bytes for path length + NUL (x) x bytes for path 1 byte for syscall stderr logging was also changed to syslog-based logging in this patch. Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 218 ++++++++++++++++++++++-- 1 file changed, 201 insertions(+), 17 deletions(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 5179d4af1..d929f83a1 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -13,11 +14,22 @@ #include #include +#include +#include +#include + #define COPY_BUFSZ 65536 #define DEFAULT_FUSERMOUNT "/bin/fusermount" #define DEFAULT_SOCKET9P_ROOT "/Transfuse" +#define RMDIR_SYSCALL 0 +#define UNLINK_SYSCALL 1 +#define MKDIR_SYSCALL 2 +#define SYMLINK_SYSCALL 3 +#define TRUNCATE_SYSCALL 4 +// these could be turned into an enum probably but... C standard nausea + char * default_fusermount = DEFAULT_FUSERMOUNT; char * default_socket9p_root = DEFAULT_SOCKET9P_ROOT; char * usage = @@ -47,12 +59,27 @@ typedef struct { int to; } copy_thread_state; +#include +#ifdef SYS_gettid +pid_t gettid() { + return syscall(SYS_gettid); +} +#else +#error "SYS_gettid not defined" +#endif + void die(int exit_code, const char * perror_arg, const char * fmt, ...) { va_list argp; + int in_errno = errno; va_start(argp, fmt); - vfprintf(stderr, fmt, argp); + vsyslog(LOG_CRIT, fmt, argp); va_end(argp); - if (perror_arg != NULL) perror(perror_arg); + 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)); + } exit(exit_code); } @@ -142,7 +169,7 @@ void copy(copy_thread_state * copy_state) { die(1, "", "copy %s trace: error writing %s: ", descr, trace_path); if (write_count != read_count) - die(1, NULL, "copy %s trace: read %d but only write %d\n", + die(1, NULL, "copy %s trace: read %d but only wrote %d\n", descr, read_count, write_count); close(trace_fd); @@ -153,7 +180,7 @@ void copy(copy_thread_state * copy_state) { if (write_count == -1) die(1, "", "copy %s: error writing: ", descr); if (write_count != read_count) - die(1, NULL, "copy %s: read %d by only wrote %d\n", + die(1, NULL, "copy %s: read %d but only wrote %d\n", descr, read_count, write_count); } @@ -270,7 +297,7 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { if (WEXITSTATUS(status)) die(1, NULL, "fusermount exited with code %d\n", WEXITSTATUS(status)); - if (debug) fprintf(stderr, "about to recv_fd from fusermount\n"); + if (debug) syslog(LOG_DEBUG, "about to recv_fd from fusermount"); fd = recv_fd(fuse_socks[1]); if (fd == -1) @@ -336,7 +363,7 @@ void do_write(connection_state * connection, int fuse) { copy_clean_to(copy_state); } -void * handle_connection(connection_state * connection) { +void * mount_connection(connection_state * connection) { char ** optv; int fuse; char * buf; @@ -355,8 +382,142 @@ void * handle_connection(connection_state * connection) { return NULL; } -void * handle_connection_thread(void * connection) { - return handle_connection((connection_state *) connection); +void * mount_thread(void * connection) { + return mount_connection((connection_state *) connection); +} + +void write_pid(connection_state * connection) { + int write_fd; + char * write_path; + pid_t pid = gettid(); + char * pid_s; + int pid_s_len, write_count; + + if (asprintf(&write_path, "%s/connections/%ld/write", + connection->params->socket9p_root, connection->id) == -1) + die(1, "Couldn't allocate write path", ""); + + write_fd = open(write_path, O_WRONLY); + if (write_fd == -1) + die(1, "couldn't open write path", "For connection %ld, ", connection->id); + + if (asprintf(&pid_s, "%lld", (long long) pid) == -1) + die(1, "Couldn't allocate pid string", ""); + + pid_s_len = strlen(pid_s); + + write_count = write(write_fd, pid_s, pid_s_len); + if (write_count == -1) + die(1, "Error writing pid", ""); + + if (write_count != pid_s_len) + die(1, NULL, "Error writing pid %s to socket: only wrote %d bytes\n", + pid_s, write_count); + + close(write_fd); + free(pid_s); + free(write_path); +} + +void perform_syscall(uint8_t syscall, char path[]) { + char * name; + int r = 0; + + switch (syscall) { + + case RMDIR_SYSCALL: + name = "rmdir"; + r = rmdir(path); + break; + + case UNLINK_SYSCALL: + name = "unlink"; + r = unlink(path); + break; + + case MKDIR_SYSCALL: + name = "mkdir"; + r = mkdir(path, 00000); + break; + + case SYMLINK_SYSCALL: + name = "symlink"; + r = symlink(".",path); + break; + + case TRUNCATE_SYSCALL: + name = "truncate"; + r = truncate(path, 0); + break; + + default: + die(1, NULL, "Unknown event syscall %" PRIu8, syscall); + } + + if (r != 0) syslog(LOG_INFO, "Event %s error: %s", name, strerror(errno)); +} + +void * event_thread(void * connection_ptr) { + char * read_path; + int read_fd; + int read_count, event_len, path_len; + void * buf; + connection_state * connection = connection_ptr; + + char * path; + uint8_t syscall; + void * msg; + + write_pid(connection); + + if (asprintf(&read_path, "%s/connections/%ld/read", + connection->params->socket9p_root, connection->id) == -1) + die(1, "Couldn't allocate read path", ""); + + read_fd = open(read_path, O_RDONLY); + if (read_fd == -1) + die(1, "couldn't open read path", "For connection %ld, ", connection->id); + + buf = must_malloc("incoming event buffer", COPY_BUFSZ); + + while(1) { + read_count = read(read_fd, buf, COPY_BUFSZ); + if (read_count == -1) die(1, "event thread: error reading", ""); + + event_len = (int) ntohs(*((uint16_t *) buf)); + + if (debug) syslog(LOG_DEBUG, "read %d bytes from connection %ld", + read_count, connection->id); + + if (read_count != event_len) { + syslog(LOG_ERR, "event thread: only read %d of %d", + read_count, event_len); + + msg = must_malloc("event hex", read_count * 2 + 1); + for (int i = 0; i < read_count; i++) { + sprintf(((char *) msg) + (i * 2),"%02x",(int) (((char *) buf)[i])); + } + ((char *) msg)[read_count * 2] = 0; + syslog(LOG_ERR, "message: %s", (char *) msg); + free(msg); + + continue; + } + + path_len = (int) ntohs(*(((uint16_t *) buf) + 1)); + // TODO: could check the path length isn't a lie here + path = (char *) (((uint8_t *) buf) + 4); + // TODO: could check the path is NUL terminated here + syscall = *(((uint8_t *) buf) + 4 + path_len); + + // TODO: should this be in another thread? + perform_syscall(syscall, path); + } + + close(read_fd); + free(buf); + free(read_path); + return NULL; } void toggle_debug(int sig) { @@ -464,6 +625,8 @@ void process_events(char * events_path, int events, parameters * params) { long conn_id; pthread_t child; connection_state * conn; + char * connection_type; + void * (*connection_handler_thread)(void *); while (1) { read_count = read(events, buf, ID_LEN - 1); @@ -473,31 +636,50 @@ void process_events(char * events_path, int events, parameters * params) { // TODO: this is probably the 9p server's fault due to // not dropping the read 0 to force short read if // the real read is flushed - fprintf(stderr, "read 0 from event stream %s\n", events_path); + syslog(LOG_WARNING, "read 0 from event stream %s", events_path); continue; } buf[read_count] = 0x0; + if (read_count < 2) { + die(1, NULL, "Event connection id isn't long enough"); + } + errno = 0; - conn_id = strtol(buf, NULL, 10); + conn_id = strtol(buf + 1, NULL, 10); if (errno) die(1, "failed", "Connection id of string '%s'", buf); - if (debug) fprintf(stderr, "handle connection %ld\n", conn_id); + if (debug) syslog(LOG_DEBUG, "handle connection %ld", conn_id); conn = (connection_state *) must_malloc("connection state", sizeof(connection_state)); conn->id = conn_id; conn->params = params; + switch (buf[0]) { + case 'm': + connection_type = "mount"; + connection_handler_thread = mount_thread; + break; + case 'e': + connection_type = "event"; + connection_handler_thread = event_thread; + break; + default: + die(1, NULL, "Unknown connection type '%c'", buf[0]); + } + if ((errno = pthread_create(&child, NULL, - handle_connection_thread, conn))) - die(1, "", "Couldn't create thread for connection '%ld': ", conn_id); + connection_handler_thread, conn))) + die(1, "", "Couldn't create thread for %s connection '%ld': ", + connection_type, conn_id); if ((errno = pthread_detach(child))) - die(1, "", "Couldn't detach thread for connection '%ld': ", conn_id); + die(1, "", "Couldn't detach thread for %s connection '%ld': ", + connection_type, conn_id); - if (debug) fprintf(stderr, "thread spawned\n"); + if (debug) syslog(LOG_DEBUG, "thread spawned"); } } @@ -506,6 +688,8 @@ int main(int argc, char * argv[]) { parameters params; char * events_path; + openlog(argv[0], LOG_CONS, LOG_DAEMON); + parse_parameters(argc, argv, ¶ms); setup_debug(); @@ -517,8 +701,8 @@ int main(int argc, char * argv[]) { events = open(events_path, O_RDONLY | O_CLOEXEC); if (events != -1) process_events(events_path, events, ¶ms); - fprintf(stderr, "Failed to open events path %s: ", events_path); - perror(""); + syslog(LOG_CRIT, "Failed to open events path %s: %s", + events_path, strerror(errno)); free(events_path); return 1; } From 58ded96b2958c0f7b96e63cf9f31672deb4d7c21 Mon Sep 17 00:00:00 2001 From: David Sheets Date: Thu, 17 Mar 2016 11:37:39 +0000 Subject: [PATCH 2/3] transfused: fix usage msg, remove syslog, use start-stop-daemon logging Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 47 ++++++++++--------------- 1 file changed, 19 insertions(+), 28 deletions(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index d929f83a1..64b5e369c 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -4,7 +4,6 @@ #include #include #include -#include #include #include @@ -60,26 +59,17 @@ typedef struct { } copy_thread_state; #include -#ifdef SYS_gettid + pid_t gettid() { return syscall(SYS_gettid); } -#else -#error "SYS_gettid not defined" -#endif 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); + vfprintf(stderr, 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)); - } + if (perror_arg != NULL) perror(perror_arg); exit(exit_code); } @@ -297,7 +287,7 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { if (WEXITSTATUS(status)) die(1, NULL, "fusermount exited with code %d\n", WEXITSTATUS(status)); - if (debug) syslog(LOG_DEBUG, "about to recv_fd from fusermount"); + if (debug) fprintf(stderr, "about to recv_fd from fusermount\n"); fd = recv_fd(fuse_socks[1]); if (fd == -1) @@ -454,7 +444,7 @@ void perform_syscall(uint8_t syscall, char path[]) { die(1, NULL, "Unknown event syscall %" PRIu8, syscall); } - if (r != 0) syslog(LOG_INFO, "Event %s error: %s", name, strerror(errno)); + if (r != 0) fprintf(stderr, "Event %s error: %s", name, strerror(errno)); } void * event_thread(void * connection_ptr) { @@ -486,19 +476,19 @@ void * event_thread(void * connection_ptr) { event_len = (int) ntohs(*((uint16_t *) buf)); - if (debug) syslog(LOG_DEBUG, "read %d bytes from connection %ld", - read_count, connection->id); + if (debug) fprintf(stderr, "read %d bytes from connection %ld\n", + read_count, connection->id); if (read_count != event_len) { - syslog(LOG_ERR, "event thread: only read %d of %d", - read_count, event_len); + fprintf(stderr, "event thread: only read %d of %d\n", + read_count, event_len); msg = must_malloc("event hex", read_count * 2 + 1); for (int i = 0; i < read_count; i++) { sprintf(((char *) msg) + (i * 2),"%02x",(int) (((char *) buf)[i])); } ((char *) msg)[read_count * 2] = 0; - syslog(LOG_ERR, "message: %s", (char *) msg); + fprintf(stderr, "message: %s\n", (char *) msg); free(msg); continue; @@ -571,7 +561,10 @@ void parse_parameters(int argc, char * argv[], parameters * params) { } } - if (errflg) die(2, NULL, usage); + if (errflg) { + fprintf(stderr, "%s", usage); + exit(2); + } if (params->pidfile != NULL && access(params->pidfile, W_OK)) if (errno != ENOENT) @@ -636,7 +629,7 @@ void process_events(char * events_path, int events, parameters * params) { // TODO: this is probably the 9p server's fault due to // not dropping the read 0 to force short read if // the real read is flushed - syslog(LOG_WARNING, "read 0 from event stream %s", events_path); + fprintf(stderr, "read 0 from event stream %s\n", events_path); continue; } @@ -650,7 +643,7 @@ void process_events(char * events_path, int events, parameters * params) { conn_id = strtol(buf + 1, NULL, 10); if (errno) die(1, "failed", "Connection id of string '%s'", buf); - if (debug) syslog(LOG_DEBUG, "handle connection %ld", conn_id); + if (debug) fprintf(stderr, "handle connection %ld\n", conn_id); conn = (connection_state *) must_malloc("connection state", sizeof(connection_state)); @@ -679,7 +672,7 @@ void process_events(char * events_path, int events, parameters * params) { die(1, "", "Couldn't detach thread for %s connection '%ld': ", connection_type, conn_id); - if (debug) syslog(LOG_DEBUG, "thread spawned"); + if (debug) fprintf(stderr, "thread spawned\n"); } } @@ -688,8 +681,6 @@ int main(int argc, char * argv[]) { parameters params; char * events_path; - openlog(argv[0], LOG_CONS, LOG_DAEMON); - parse_parameters(argc, argv, ¶ms); setup_debug(); @@ -701,8 +692,8 @@ int main(int argc, char * argv[]) { events = open(events_path, O_RDONLY | O_CLOEXEC); if (events != -1) process_events(events_path, events, ¶ms); - syslog(LOG_CRIT, "Failed to open events path %s: %s", - events_path, strerror(errno)); + fprintf(stderr, "Failed to open events path %s: %s\n", + events_path, strerror(errno)); free(events_path); return 1; } From 16101e66c3a659f94c3454dcbdb73a28b26ddc20 Mon Sep 17 00:00:00 2001 From: David Sheets Date: Fri, 18 Mar 2016 11:21:42 +0000 Subject: [PATCH 3/3] transfused: add start-up log, self-log trigger, and run-time log flags During start-up, logs are sent to syslog and stderr and the console if syslog is not available. -l logfile will also send the logs to logfile but only prior to any log trigger events. -m mount_trigger lets the user specify the mount point to watch for to begin sending logs to -t triggered_log file which may be on the newly mounted file system. Log concatenation and rollover are not implemented, yet. Logging functionality has been separated into transfused_log.c. Locks have been placed around shared fds. The writer thread is now symmetric to the reader thread instead of inheriting the parent's thread in order to trigger log switchover after the file system proxy has started. The coredump size rlimit has been lifted. Signed-off-by: David Sheets --- alpine/packages/transfused/Makefile | 7 +- .../packages/transfused/etc/init.d/transfused | 22 +- alpine/packages/transfused/transfused.c | 284 +++++++++++++----- alpine/packages/transfused/transfused.h | 22 ++ alpine/packages/transfused/transfused_log.c | 117 ++++++++ alpine/packages/transfused/transfused_log.h | 15 + 6 files changed, 381 insertions(+), 86 deletions(-) create mode 100644 alpine/packages/transfused/transfused.h create mode 100644 alpine/packages/transfused/transfused_log.c create mode 100644 alpine/packages/transfused/transfused_log.h diff --git a/alpine/packages/transfused/Makefile b/alpine/packages/transfused/Makefile index d5739d5b7..f8a9b420f 100644 --- a/alpine/packages/transfused/Makefile +++ b/alpine/packages/transfused/Makefile @@ -1,6 +1,9 @@ .PHONY: all -DEPS=transfused.c +HDR=transfused.h transfused_log.h +SRC=transfused.c transfused_log.c +DEPS=$(HDR) $(SRC) + all: Dockerfile $(DEPS) docker build -t transfused:build . @@ -8,7 +11,7 @@ all: Dockerfile $(DEPS) chmod 755 transfused transfused: $(DEPS) - gcc -g -static -Wall -Werror -o transfused transfused.c + gcc -g -static -Wall -Werror -o transfused $(SRC) clean: rm -f transfused diff --git a/alpine/packages/transfused/etc/init.d/transfused b/alpine/packages/transfused/etc/init.d/transfused index a2731d051..063322c5d 100755 --- a/alpine/packages/transfused/etc/init.d/transfused +++ b/alpine/packages/transfused/etc/init.d/transfused @@ -13,16 +13,28 @@ start() ebegin "Starting FUSE socket passthrough" - PIDFILE=/var/run/transfused.pid - LOGFILE=/var/log/transfused.log + if cat /proc/cmdline | grep -q 'com.docker.driverDir' + then + DRIVERDIR="/Mac$(cat /proc/cmdline | sed -e 's/.*com.docker.driverDir="//' -e 's/".*//')" + RUNTIME_LOGFILE=${DRIVERDIR}/log/transfused.log + else + ID=$(LC_CTYPE=C tr -dc A-Za-z0-9 < /dev/urandom | head -c 8) + RUNTIME_LOGFILE="/Mac/private/tmp/transfused_${ID}.log" + fi + + PIDFILE=/var/run/transfused.pid + STARTUP_LOGFILE=/var/transfused_start.log + MOUNT_TRIGGER=/Mac start-stop-daemon --start --quiet \ --background \ --exec /sbin/transfused \ --pidfile ${PIDFILE} \ - --stderr "${LOGFILE}" \ - --stdout "${LOGFILE}" \ - -- -p "${PIDFILE}" + -- \ + -p "${PIDFILE}" \ + -l "${STARTUP_LOGFILE}" \ + -m "${MOUNT_TRIGGER}" \ + -t "${RUNTIME_LOGFILE}" eend $? "Failed to start transfused" } diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 64b5e369c..7ad5aaf0f 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -3,7 +3,7 @@ #include #include -#include +#include #include #include @@ -17,6 +17,11 @@ #include #include +#include +#include + +#include "transfused_log.h" + #define COPY_BUFSZ 65536 #define DEFAULT_FUSERMOUNT "/bin/fusermount" @@ -33,23 +38,16 @@ char * default_fusermount = DEFAULT_FUSERMOUNT; char * default_socket9p_root = DEFAULT_SOCKET9P_ROOT; char * usage = "usage: transfused [-p pidfile] [-9 socket9p_root] [-f fusermount]\n" + " [-l logfile] [-m mount_trigger] [-t triggerlog]\n" " -p pidfile\tthe path at which to write the pid of the process\n" " -9 " DEFAULT_SOCKET9P_ROOT "\tthe root of the 9p socket file system\n" - " -f " DEFAULT_FUSERMOUNT "\tthe fusermount executable to use\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"; int debug = 0; -typedef struct { - char * socket9p_root; - char * fusermount; - char * pidfile; -} parameters; - -typedef struct { - parameters * params; - long id; -} connection_state; - typedef struct { char * descr; long connection; @@ -64,15 +62,6 @@ pid_t gettid() { return syscall(SYS_gettid); } -void die(int exit_code, const char * perror_arg, const char * fmt, ...) { - va_list argp; - va_start(argp, fmt); - vfprintf(stderr, fmt, argp); - va_end(argp); - if (perror_arg != NULL) perror(perror_arg); - exit(exit_code); -} - void * must_malloc(char *const descr, size_t size) { void * ptr; @@ -82,7 +71,29 @@ void * must_malloc(char *const descr, size_t size) { return ptr; } -char ** read_opts(connection_state * connection, char * buf) { +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); +} + +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); +} + +void lock(char *const descr, pthread_mutex_t * mutex) { + if ((errno = pthread_mutex_lock(mutex))) + die(1, "", "lock %s: ", descr); +} + +void unlock(char *const descr, pthread_mutex_t * mutex) { + if ((errno = pthread_mutex_unlock(mutex))) + die(1, "", "unlock %s: ", descr); +} + +char ** read_opts(connection_t * connection, char * buf) { int read_fd; char * read_path; int read_count; @@ -159,7 +170,7 @@ void copy(copy_thread_state * copy_state) { die(1, "", "copy %s trace: error writing %s: ", descr, trace_path); if (write_count != read_count) - die(1, NULL, "copy %s trace: read %d but only wrote %d\n", + die(1, NULL, "copy %s trace: read %d but only wrote %d", descr, read_count, write_count); close(trace_fd); @@ -170,7 +181,7 @@ void copy(copy_thread_state * copy_state) { if (write_count == -1) die(1, "", "copy %s: error writing: ", descr); if (write_count != read_count) - die(1, NULL, "copy %s: read %d but only wrote %d\n", + die(1, NULL, "copy %s: read %d but only wrote %d", descr, read_count, write_count); } @@ -203,6 +214,10 @@ void * copy_clean_to(copy_thread_state * copy_state) { return NULL; } +void * copy_clean_to_thread(void * copy_state) { + return (copy_clean_to((copy_thread_state *) copy_state)); +} + int recv_fd(int sock) { int ret; int fd = -1; @@ -239,8 +254,7 @@ int recv_fd(int sock) { } // optv must be null-terminated -int get_fuse_sock(char * fusermount, char *const optv[]) { - int optc; +int get_fuse_sock(connection_t * conn, int optc, char *const optv[]) { char ** argv; char * envp[2]; pid_t fusermount_pid; @@ -249,13 +263,17 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { int fd; // prepare argv from optv - for (optc = 0; optv[optc] != NULL; optc++) {} - argv = (char **) must_malloc("fusermount argv", (optc + 2) * sizeof(char *)); - argv[0] = fusermount; + 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); + // 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", ""); @@ -269,7 +287,7 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { // fork and exec fusermount fusermount_pid = fork(); if (!fusermount_pid) // child - if (execve(fusermount, argv, envp)) + if (execve(argv[0], argv, envp)) die(1, "Failed to execute fusermount", ""); // parent @@ -282,16 +300,16 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { // wait for fusermount to return waitpid(fusermount_pid, &status, 0); if (!WIFEXITED(status)) - die(1, NULL, "fusermount terminated abnormally\n"); + die(1, NULL, "fusermount terminated abnormally"); if (WEXITSTATUS(status)) - die(1, NULL, "fusermount exited with code %d\n", WEXITSTATUS(status)); + die(1, NULL, "fusermount exited with code %d", WEXITSTATUS(status)); - if (debug) fprintf(stderr, "about to recv_fd from fusermount\n"); + if (debug) log_time(conn, "about to recv_fd from fusermount\n"); fd = recv_fd(fuse_socks[1]); if (fd == -1) - die(1, NULL, "Couldn't receive fd over FUSE socket\n"); + die(1, NULL, "Couldn't receive fd over FUSE socket"); // close the read end of the socket close(fuse_socks[1]); @@ -299,7 +317,7 @@ int get_fuse_sock(char * fusermount, char *const optv[]) { return fd; } -void start_reader(connection_state * connection, int fuse) { +void start_reader(connection_t * connection, int fuse) { int read_fd; char * read_path; pthread_t child; @@ -326,13 +344,14 @@ void start_reader(connection_state * connection, int fuse) { connection->id); if ((errno = pthread_detach(child))) - die (1, "", "couldn't detach read copy thread for connection '%ld': ", - connection->id); + die(1, "", "couldn't detach read copy thread for connection %ld: ", + connection->id); } -void do_write(connection_state * connection, int fuse) { +void start_writer(connection_t * connection, int fuse) { int write_fd; char * write_path; + pthread_t child; copy_thread_state * copy_state; if (asprintf(&write_path, "%s/connections/%ld/write", @@ -350,33 +369,76 @@ void do_write(connection_state * connection, int fuse) { copy_state->tag = "write"; copy_state->from = fuse; copy_state->to = write_fd; - copy_clean_to(copy_state); + if ((errno = pthread_create(&child, NULL, + copy_clean_to_thread, copy_state))) + die(1, "", "Couldn't create write copy thread for connection %ld: ", + connection->id); + + if ((errno = pthread_detach(child))) + die(1, "", "couldn't detach write copy thread for connection %ld: ", + connection->id); } -void * mount_connection(connection_state * connection) { +void * mount_connection(connection_t * conn) { + int optc; char ** optv; int fuse; char * buf; + pthread_mutex_t copy_lock; + pthread_cond_t copy_halt; + int should_halt = 0; buf = (char *) must_malloc("read_opts packet malloc", COPY_BUFSZ); - optv = read_opts(connection, buf); - fuse = get_fuse_sock(connection->params->fusermount, optv); - free(optv); + optv = read_opts(conn, buf); + + for (optc = 0; optv[optc] != NULL; optc++) {} + + fuse = get_fuse_sock(conn, optc, optv); free(buf); - start_reader(connection, fuse); - do_write(connection, fuse); - free(connection); + lock_init("copy_lock", ©_lock, NULL); + cond_init("copy_halt", ©_halt, NULL); + + 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_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 connection %ld: ", + conn->id); + unlock("copy lock", ©_lock); + + free(conn); return NULL; } void * mount_thread(void * connection) { - return mount_connection((connection_state *) connection); + return mount_connection((connection_t *) connection); } -void write_pid(connection_state * connection) { +void write_pid(connection_t * connection) { int write_fd; char * write_path; pid_t pid = gettid(); @@ -401,7 +463,7 @@ void write_pid(connection_state * connection) { die(1, "Error writing pid", ""); if (write_count != pid_s_len) - die(1, NULL, "Error writing pid %s to socket: only wrote %d bytes\n", + die(1, NULL, "Error writing pid %s to socket: only wrote %d bytes", pid_s, write_count); close(write_fd); @@ -409,7 +471,7 @@ void write_pid(connection_state * connection) { free(write_path); } -void perform_syscall(uint8_t syscall, char path[]) { +void perform_syscall(connection_t * conn, uint8_t syscall, char path[]) { char * name; int r = 0; @@ -444,7 +506,7 @@ void perform_syscall(uint8_t syscall, char path[]) { die(1, NULL, "Unknown event syscall %" PRIu8, syscall); } - if (r != 0) fprintf(stderr, "Event %s error: %s", name, strerror(errno)); + if (r != 0) log_time(conn, "Event %s error: %s\n", name, strerror(errno)); } void * event_thread(void * connection_ptr) { @@ -452,7 +514,7 @@ void * event_thread(void * connection_ptr) { int read_fd; int read_count, event_len, path_len; void * buf; - connection_state * connection = connection_ptr; + connection_t * connection = connection_ptr; char * path; uint8_t syscall; @@ -476,19 +538,19 @@ void * event_thread(void * connection_ptr) { event_len = (int) ntohs(*((uint16_t *) buf)); - if (debug) fprintf(stderr, "read %d bytes from connection %ld\n", - read_count, connection->id); + if (debug) log_time(connection, "read %d bytes from connection %ld\n", + read_count, connection->id); if (read_count != event_len) { - fprintf(stderr, "event thread: only read %d of %d\n", - read_count, event_len); + log_time(connection, "event thread: only read %d of %d\n", + read_count, event_len); msg = must_malloc("event hex", read_count * 2 + 1); for (int i = 0; i < read_count; i++) { sprintf(((char *) msg) + (i * 2),"%02x",(int) (((char *) buf)[i])); } ((char *) msg)[read_count * 2] = 0; - fprintf(stderr, "message: %s\n", (char *) msg); + log_time(connection, "message: %s\n", (char *) msg); free(msg); continue; @@ -501,7 +563,7 @@ void * event_thread(void * connection_ptr) { syscall = *(((uint8_t *) buf) + 4 + path_len); // TODO: should this be in another thread? - perform_syscall(syscall, path); + perform_syscall(connection, syscall, path); } close(read_fd); @@ -529,8 +591,14 @@ void parse_parameters(int argc, char * argv[], parameters * params) { params->pidfile = NULL; params->socket9p_root = NULL; 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); - while ((c = getopt(argc, argv, ":p:9:f:")) != -1) { + while ((c = getopt(argc, argv, ":p:9:f:l:m:t:")) != -1) { switch(c) { case 'p': @@ -545,6 +613,18 @@ void parse_parameters(int argc, char * argv[], parameters * params) { params->fusermount = optarg; break; + case 'l': + 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++; @@ -567,20 +647,47 @@ void parse_parameters(int argc, char * argv[], parameters * params) { } if (params->pidfile != NULL && access(params->pidfile, W_OK)) - if (errno != ENOENT) - die(2, "", "-p %s path to pidfile must be writable: ", params->pidfile); + if (errno != ENOENT) { + fprintf(stderr, "-p %s path to pidfile must be writable: ", + params->pidfile); + perror(""); + exit(2); + } if (params->fusermount == NULL) params->fusermount = default_fusermount; - if (access(params->fusermount, X_OK)) - die(2, "", "-f %s path to fusermount must be executable: ", - params->fusermount); + if (access(params->fusermount, X_OK)) { + fprintf(stderr, "-f %s path to fusermount must be executable: ", + params->fusermount); + perror(""); + exit(2); + } if (params->socket9p_root == NULL) params->socket9p_root = default_socket9p_root; - if (access(params->socket9p_root, X_OK)) - die(2, "", "-9 %s path to socket 9p root directory must be executable: ", - params->socket9p_root); + if (access(params->socket9p_root, X_OK)) { + fprintf(stderr, + "-9 %s path to socket 9p root directory must be executable: ", + params->socket9p_root); + perror(""); + exit(2); + } + + if (params->logfile != NULL && access(params->logfile, W_OK)) + if (errno != ENOENT) { + fprintf(stderr, "-l %s path to logfile must be writable: ", + params->logfile); + 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 write_pidfile(char * pidfile) { @@ -603,7 +710,7 @@ void write_pidfile(char * pidfile) { die(1, "", "Error writing pidfile %s: ", pidfile); if (write_count != pid_s_len) - die(1, NULL, "Error writing %s to pidfile %s: only wrote %d bytes\n", + die(1, NULL, "Error writing %s to pidfile %s: only wrote %d bytes", pid_s, pidfile, write_count); close(fd); @@ -617,11 +724,16 @@ void process_events(char * events_path, int events, parameters * params) { int read_count; long conn_id; pthread_t child; - connection_state * conn; + connection_t * conn; char * connection_type; void * (*connection_handler_thread)(void *); while (1) { + conn = (connection_t *) must_malloc("connection state", + sizeof(connection_t)); + conn->params = params; + conn->id = 0; + read_count = read(events, buf, ID_LEN - 1); if (read_count == -1) { die(1, "", "Error reading events path %s: ", events_path); @@ -629,7 +741,7 @@ void process_events(char * events_path, int events, parameters * params) { // TODO: this is probably the 9p server's fault due to // not dropping the read 0 to force short read if // the real read is flushed - fprintf(stderr, "read 0 from event stream %s\n", events_path); + log_time(conn, "read 0 from event stream %s\n", events_path); continue; } @@ -643,12 +755,9 @@ void process_events(char * events_path, int events, parameters * params) { conn_id = strtol(buf + 1, NULL, 10); if (errno) die(1, "failed", "Connection id of string '%s'", buf); - if (debug) fprintf(stderr, "handle connection %ld\n", conn_id); - - conn = (connection_state *) must_malloc("connection state", - sizeof(connection_state)); conn->id = conn_id; - conn->params = params; + + if (debug) log_time(conn, "handle connection %ld\n", conn_id); switch (buf[0]) { case 'm': @@ -672,7 +781,7 @@ void process_events(char * events_path, int events, parameters * params) { die(1, "", "Couldn't detach thread for %s connection '%ld': ", connection_type, conn_id); - if (debug) fprintf(stderr, "thread spawned\n"); + if (debug) log_time(conn, "thread spawned\n"); } } @@ -680,20 +789,37 @@ int main(int argc, char * argv[]) { int events; parameters params; char * events_path; + struct rlimit core_limit; + + 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"); + + openlog(argv[0], LOG_CONS | LOG_PERROR | LOG_NDELAY, LOG_DAEMON); parse_parameters(argc, argv, ¶ms); setup_debug(); if (params.pidfile != NULL) write_pidfile(params.pidfile); + 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); + } + if (asprintf(&events_path, "%s/events", params.socket9p_root) == -1) die(1, "Couldn't allocate events path", ""); events = open(events_path, O_RDONLY | O_CLOEXEC); if (events != -1) process_events(events_path, events, ¶ms); - fprintf(stderr, "Failed to open events path %s: %s\n", - events_path, strerror(errno)); + connection_t top; + top.params = ¶ms; + top.id = 0; + log_time(&top, "Failed to open events path %s: %s\n", + events_path, strerror(errno)); free(events_path); return 1; } diff --git a/alpine/packages/transfused/transfused.h b/alpine/packages/transfused/transfused.h new file mode 100644 index 000000000..56383b14e --- /dev/null +++ b/alpine/packages/transfused/transfused.h @@ -0,0 +1,22 @@ +#include + +typedef struct { + char * socket9p_root; + char * fusermount; + char * pidfile; + char * logfile; + char * mount_trigger; + char * trigger_log; + pthread_mutex_t fd_lock; + int logfile_fd; + int trigger_fd; +} parameters; + +typedef struct { + parameters * params; + long id; +} connection_t; + +void lock(char *const descr, pthread_mutex_t * mutex); + +void unlock(char *const descr, pthread_mutex_t * mutex); diff --git a/alpine/packages/transfused/transfused_log.c b/alpine/packages/transfused/transfused_log.c new file mode 100644 index 000000000..4d8375a15 --- /dev/null +++ b/alpine/packages/transfused/transfused_log.c @@ -0,0 +1,117 @@ +#include +#include + +#include +#include +#include +#include + +#include + +#include +#include +#include + +#include "transfused.h" + +void log_timestamp(int fd) { + char timestamp[26]; + int msec; + struct tm* tm_info; + struct timeval tv; + + gettimeofday(&tv, NULL); + + msec = lrint(tv.tv_usec/1000.0); + if (msec >= 1000) { + msec -= 1000; + tv.tv_sec++; + } + + tm_info = localtime(&tv.tv_sec); + + strftime(timestamp, 26, "%Y-%m-%d %H:%M:%S", tm_info); + 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)); + } + 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, ...) { + va_list args; + + va_start(args, fmt); + + vlog_time_locked(connection, fmt, args); + + va_end(args); +} + +void log_time(connection_t * connection, 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); + + va_end(args); +} + +void log_continue_locked(connection_t * connection, const char * fmt, ...) { + va_list args; + + va_start(args, fmt); + + vlog_locked(connection, fmt, args); + + va_end(args); +} + +void log_continue(connection_t * connection, 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); + + va_end(args); +} diff --git a/alpine/packages/transfused/transfused_log.h b/alpine/packages/transfused/transfused_log.h new file mode 100644 index 000000000..ed8f4d4c2 --- /dev/null +++ b/alpine/packages/transfused/transfused_log.h @@ -0,0 +1,15 @@ +#include "transfused.h" + +void die(int exit_code, const char * perror_arg, const char * fmt, ...); + +void vlog_locked(connection_t * conn, const char * fmt, va_list args); + +void vlog_time_locked(connection_t * conn, const char * fmt, va_list args); + +void log_time_locked(connection_t * connection, const char * fmt, ...); + +void log_time(connection_t * connection, const char * fmt, ...); + +void log_continue_locked(connection_t * connection, const char * fmt, ...); + +void log_continue(connection_t * connection, const char * fmt, ...);