transfused: move logging off of the event actuation thread

Signed-off-by: David Sheets <david.sheets@docker.com>

alpine/packages/transfused/transfused.c

@@ -511,7 +511,9 @@ void perform_syscall(connection_t * conn, uint8_t syscall, char path[]) {
     die(1, NULL, "Unknown event syscall %" PRIu8, syscall);
   }
 
-  if (r != 0) log_time(conn, "Event %s error: %s\n", name, strerror(errno));
+  if (r != 0)
+    thread_log_time(conn, "Event %s %s error: %s\n",
+                    name, path, strerror(errno));
 }
 
 void * event_thread(void * connection_ptr) {
@@ -525,6 +527,10 @@ void * event_thread(void * connection_ptr) {
   uint8_t syscall;
   void * msg;
 
+  // This thread registers with the mounted file system as being an
+  // fsnotify event actuator. Other mounted file system interactions
+  // (such as self-logging) SHOULD NOT occur on this thread.
+
   write_pid(connection);
 
   if (asprintf(&read_path, "%s/connections/%ld/read",
@@ -543,19 +549,20 @@ void * event_thread(void * connection_ptr) {
 
     event_len = (int) ntohs(*((uint16_t *) buf));
 
-    if (debug) log_time(connection, "read %d bytes from connection %ld\n",
+    if (debug)
-                        read_count, connection->id);
+      thread_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",
+      thread_log_time(connection, "event thread: only read %d of %d\n",
-               read_count, event_len);
+                      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);
+      thread_log_time(connection, "message: %s\n", (char *) msg);
       free(msg);
 
       continue;
@@ -730,7 +737,6 @@ void process_events(char * events_path, int events, parameters * params) {
     long conn_id;
     pthread_t child;
     connection_t * conn;
-    char * connection_type;
     void * (*connection_handler_thread)(void *);
 
     while (1) {
@@ -766,11 +772,11 @@ void process_events(char * events_path, int events, parameters * params) {
 
       switch (buf[0]) {
       case 'm':
-        connection_type = "mount";
+        conn->type_descr = "mount";
         connection_handler_thread = mount_thread;
         break;
       case 'e':
-        connection_type = "event";
+        conn->type_descr = "event";
         connection_handler_thread = event_thread;
         break;
       default:
@@ -780,11 +786,11 @@ void process_events(char * events_path, int events, parameters * params) {
       if ((errno = pthread_create(&child, NULL,
                                   connection_handler_thread, conn)))
         die(1, "", "Couldn't create thread for %s connection '%ld': ",
-            connection_type, conn_id);
+            conn->type_descr, conn_id);
 
       if ((errno = pthread_detach(child)))
         die(1, "", "Couldn't detach thread for %s connection '%ld': ",
-            connection_type, conn_id);
+            conn->type_descr, conn_id);
 
       if (debug) log_time(conn, "thread spawned\n");
     }

alpine/packages/transfused/transfused.h

@@ -15,8 +15,11 @@ typedef struct {
 typedef struct {
   parameters * params;
   long id;
+  char * type_descr;
 } connection_t;
 
+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);

alpine/packages/transfused/transfused_log.c

@@ -94,6 +94,50 @@ void log_time(connection_t * connection, const char * fmt, ...) {
   va_end(args);
 }
 
+typedef struct {
+  connection_t * connection;
+  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);
+
+  free(log_state->msg);
+  free(log_state);
+
+  return NULL;
+}
+
+void thread_log_time(connection_t * conn, const char * fmt, ...) {
+  pthread_t logger;
+  va_list args;
+  log_thread_state * log_state;
+
+  log_state = must_malloc("thread_log_time log_state",
+                          sizeof(log_thread_state));
+  log_state->connection = conn;
+
+  va_start(args, fmt);
+  if (vasprintf(&log_state->msg, fmt, args) == -1)
+    die(1, "Couldn't allocate thread_log_time message", "");
+  va_end(args);
+
+  // TODO: We currently spawn a new thread for every message. This is
+  // far from ideal but fine for now as we anticipate thread-sensitive
+  // log demand to be low.
+
+  if ((errno = pthread_create(&logger, NULL, log_time_thread, log_state)))
+    die(1, "", "Couldn't create log thread for %s connection '%ld': ",
+        conn->type_descr, conn->id);
+
+  if ((errno = pthread_detach(logger)))
+    die(1, "", "Couldn't detach thread for %s connection '%ld': ",
+        conn->type_descr, conn->id);
+
+}
+
 void log_continue_locked(connection_t * connection, const char * fmt, ...) {
   va_list args;
 

alpine/packages/transfused/transfused_log.h

@@ -10,6 +10,8 @@ void log_time_locked(connection_t * connection, const char * fmt, ...);
 
 void log_time(connection_t * connection, const char * fmt, ...);
 
+void thread_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, ...);