Merge pull request #48 from dsheets/transfused-events

transfused: change protocol to support events, add syslog logging

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

alpine/packages/transfused/etc/init.d/transfused

@@ -13,16 +13,28 @@ start()
 
 	ebegin "Starting FUSE socket passthrough"
 
+        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
-	LOGFILE=/var/log/transfused.log
+        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"
 }

alpine/packages/transfused/transfused.c

@@ -3,7 +3,7 @@
 
 #include <stdlib.h>
 #include <string.h>
-#include <stdarg.h>
+#include <syslog.h>
 
 #include <stdio.h>
 #include <unistd.h>
@@ -13,32 +13,41 @@
 #include <pthread.h>
 #include <signal.h>
 
+#include <netinet/in.h>
+#include <inttypes.h>
+#include <sys/stat.h>
+
+#include <sys/time.h>
+#include <sys/resource.h>
+
+#include "transfused_log.h"
+
 #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 =
   "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;
@@ -47,13 +56,10 @@ typedef struct {
   int to;
 } copy_thread_state;
 
-void die(int exit_code, const char * perror_arg, const char * fmt, ...) {
+#include <sys/syscall.h>
-  va_list argp;
+
-  va_start(argp, fmt);
+pid_t gettid() {
-  vfprintf(stderr, fmt, argp);
+  return syscall(SYS_gettid);
-  va_end(argp);
-  if (perror_arg != NULL) perror(perror_arg);
-  exit(exit_code);
 }
 
 void * must_malloc(char *const descr, size_t size) {
@@ -65,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;
@@ -142,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 write %d\n",
+        die(1, NULL, "copy %s trace: read %d but only wrote %d",
             descr, read_count, write_count);
 
       close(trace_fd);
@@ -153,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 by only wrote %d\n",
+      die(1, NULL, "copy %s: read %d but only wrote %d",
           descr, read_count, write_count);
   }
 
@@ -186,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;
@@ -222,8 +254,7 @@ int recv_fd(int sock) {
 }
 
 // optv must be null-terminated
-int get_fuse_sock(char * fusermount, char *const optv[]) {
+int get_fuse_sock(connection_t * conn, int optc, char *const optv[]) {
-  int optc;
   char ** argv;
   char * envp[2];
   pid_t fusermount_pid;
@@ -232,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", "");
@@ -252,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
@@ -265,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]);
@@ -282,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;
@@ -309,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': ",
+    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",
@@ -333,30 +369,207 @@ 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 * handle_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);
+  optv = read_opts(conn, buf);
-  fuse = get_fuse_sock(connection->params->fusermount, optv);
+
-  free(optv);
+  for (optc = 0; optv[optc] != NULL; optc++) {}
+
+  fuse = get_fuse_sock(conn, optc, optv);
   free(buf);
 
-  start_reader(connection, fuse);
+  lock_init("copy_lock", &copy_lock, NULL);
-  do_write(connection, fuse);
+  cond_init("copy_halt", &copy_halt, NULL);
-  free(connection);
+
+  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", &copy_lock);
+  while (!should_halt)
+    if ((errno = pthread_cond_wait(&copy_halt, &copy_lock)))
+      die(1, "", "Couldn't wait for copy halt for connection %ld: ",
+          conn->id);
+  unlock("copy lock", &copy_lock);
+
+  free(conn);
 
   return NULL;
 }
 
-void * handle_connection_thread(void * connection) {
+void * mount_thread(void * connection) {
-  return handle_connection((connection_state *) connection);
+  return mount_connection((connection_t *) connection);
+}
+
+void write_pid(connection_t * 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",
+        pid_s, write_count);
+
+  close(write_fd);
+  free(pid_s);
+  free(write_path);
+}
+
+void perform_syscall(connection_t * conn, 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) log_time(conn, "Event %s error: %s\n", 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_t * 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) log_time(connection, "read %d bytes from connection %ld\n",
+                        read_count, connection->id);
+
+    if (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;
+      log_time(connection, "message: %s\n", (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(connection, syscall, path);
+  }
+
+  close(read_fd);
+  free(buf);
+  free(read_path);
+  return NULL;
 }
 
 void toggle_debug(int sig) {
@@ -378,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", &params->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':
@@ -394,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++;
@@ -410,23 +641,53 @@ 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)
+    if (errno != ENOENT) {
-      die(2, "", "-p %s path to pidfile must be writable: ", params->pidfile);
+      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))
+  if (access(params->fusermount, X_OK)) {
-    die(2, "", "-f %s path to fusermount must be executable: ",
+    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))
+  if (access(params->socket9p_root, X_OK)) {
-    die(2, "", "-9 %s path to socket 9p root directory must be executable: ",
+    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) {
@@ -449,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);
@@ -463,9 +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);
@@ -473,31 +741,47 @@ 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;
       }
 
       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);
-
-      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':
+        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)))
+                                  connection_handler_thread, conn)))
-        die(1, "", "Couldn't create thread for connection '%ld': ", conn_id);
+        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) log_time(conn, "thread spawned\n");
     }
 }
 
@@ -505,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, &params);
   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, &params);
 
-  fprintf(stderr, "Failed to open events path %s: ", events_path);
+  connection_t top;
-  perror("");
+  top.params = &params;
+  top.id = 0;
+  log_time(&top, "Failed to open events path %s: %s\n",
+           events_path, strerror(errno));
   free(events_path);
   return 1;
 }

alpine/packages/transfused/transfused.h

@@ -0,0 +1,22 @@
+#include <pthread.h>
+
+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);

alpine/packages/transfused/transfused_log.c

@@ -0,0 +1,117 @@
+#include <errno.h>
+#include <string.h>
+
+#include <stdlib.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <pthread.h>
+
+#include <syslog.h>
+
+#include <sys/time.h>
+#include <time.h>
+#include <math.h>
+
+#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);
+}

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, ...);