shm-logging: implement i3-dump-log -f (follow)

This changes the SHM log format, it doesn’t use 0-bytes to separate
entries anymore. Instead of using lots of printf() calls in i3-dump-log,
we now do precisely one big write().

So, to be clear: i3-dump-log and i3 both need to be upgraded.
Mismatching versions will lead to garbage output (no crashes of i3, just
garbage output).

The -f flag uses an inter-process pthread_cond_t in the shared memory
header to broadcast the arrival of new messages to all i3-dump-log
processes. This internally uses futexes and thus doesn’t even mean a
kernel call in most cases. inter-process pthread_cond_ts require NPTL
(the Native Posix Thread Library, introduce in Linux 2.6).

i3-dump-log/main.c

@@ -2,7 +2,7 @@
  * vim:ts=4:sw=4:expandtab
  *
  * i3 - an improved dynamic tiling window manager
- * © 2009-2011 Michael Stapelberg and contributors (see also: LICENSE)
+ * © 2009-2012 Michael Stapelberg and contributors (see also: LICENSE)
  *
  * i3-dump-log/main.c: Dumps the i3 SHM log to stdout.
  *
@@ -28,18 +28,47 @@
 #include "shmlog.h"
 #include <i3/ipc.h>
 
+static uint32_t offset_next_write,
+                wrap_count;
+
+static i3_shmlog_header *header;
+static char *logbuffer,
+            *walk;
+
+static int check_for_wrap(void) {
+    if (wrap_count == header->wrap_count)
+        return 0;
+
+    /* The log wrapped. Print the remaining content and reset walk to the top
+     * of the log. */
+    wrap_count = header->wrap_count;
+    write(STDOUT_FILENO, walk, ((logbuffer + header->offset_last_wrap) - walk));
+    walk = logbuffer + sizeof(i3_shmlog_header);
+    return 1;
+}
+
+static void print_till_end(void) {
+    check_for_wrap();
+    int n = write(STDOUT_FILENO, walk, ((logbuffer + header->offset_next_write) - walk));
+    if (n > 0) {
+        walk += n;
+    }
+}
+
 int main(int argc, char *argv[]) {
     int o, option_index = 0;
-    bool verbose = false;
+    bool verbose = false,
+         follow = false;
 
     static struct option long_options[] = {
         {"version", no_argument, 0, 'v'},
         {"verbose", no_argument, 0, 'V'},
+        {"follow", no_argument, 0, 'f'},
         {"help", no_argument, 0, 'h'},
         {0, 0, 0, 0}
     };
 
-    char *options_string = "s:vVh";
+    char *options_string = "s:vfVh";
 
     while ((o = getopt_long(argc, argv, options_string, long_options, &option_index)) != -1) {
         if (o == 'v') {
@@ -47,9 +76,11 @@ int main(int argc, char *argv[]) {
             return 0;
         } else if (o == 'V') {
             verbose = true;
+        } else if (o == 'f') {
+            follow = true;
         } else if (o == 'h') {
             printf("i3-dump-log " I3_VERSION "\n");
-            printf("i3-dump-log [-s <socket>]\n");
+            printf("i3-dump-log [-f] [-s <socket>]\n");
             return 0;
         }
     }
@@ -90,45 +121,61 @@ int main(int argc, char *argv[]) {
 
     struct stat statbuf;
 
-    int logbuffer_shm = shm_open(shmname, O_RDONLY, 0);
+    /* NB: While we must never read, we need O_RDWR for the pthread condvar. */
+    int logbuffer_shm = shm_open(shmname, O_RDWR, 0);
     if (logbuffer_shm == -1)
         err(EXIT_FAILURE, "Could not shm_open SHM segment for the i3 log (%s)", shmname);
 
     if (fstat(logbuffer_shm, &statbuf) != 0)
         err(EXIT_FAILURE, "stat(%s)", shmname);
 
-    char *logbuffer = mmap(NULL, statbuf.st_size, PROT_READ, MAP_SHARED, logbuffer_shm, 0);
+    /* NB: While we must never read, we need O_RDWR for the pthread condvar. */
+    logbuffer = mmap(NULL, statbuf.st_size, PROT_READ | PROT_WRITE, MAP_SHARED, logbuffer_shm, 0);
     if (logbuffer == MAP_FAILED)
         err(EXIT_FAILURE, "Could not mmap SHM segment for the i3 log");
 
-    i3_shmlog_header *header = (i3_shmlog_header*)logbuffer;
+    header = (i3_shmlog_header*)logbuffer;
 
     if (verbose)
         printf("next_write = %d, last_wrap = %d, logbuffer_size = %d, shmname = %s\n",
                header->offset_next_write, header->offset_last_wrap, header->size, shmname);
-    int chars;
+    walk = logbuffer + header->offset_next_write;
-    char *walk = logbuffer + header->offset_next_write;
-    /* Skip the first line, it very likely is mangled. Not a problem, though,
-     * the log is chatty enough to have plenty lines left. */
-    while (*walk != '\0')
-        walk++;
 
-    /* Print the oldest log lines. We use printf("%s") to stop on \0. */
+    /* We first need to print old content in case there was at least one
-    while (walk < (logbuffer + header->offset_last_wrap)) {
+     * wrapping already. */
-        chars = printf("%s", walk);
+
-        /* Shortcut: If there are two consecutive \0 bytes, this part of the
+    if (*walk != '\0') {
-         * buffer was never touched. To not call printf() for every byte of the
+        /* In case there was a write to the buffer already, skip the first
-         * buffer, we directly exit the loop. */
+         * old line, it very likely is mangled. Not a problem, though, the log
-        if (*walk == '\0' && *(walk+1) == '\0')
+         * is chatty enough to have plenty lines left. */
-            break;
+        while (*walk != '\n')
-        walk += (chars > 0 ? chars : 1);
+            walk++;
+        walk++;
     }
 
+    /* In case there was no wrapping, this is a no-op, otherwise it prints the
+     * old lines. */
+    wrap_count = 0;
+    check_for_wrap();
+
     /* Then start from the beginning and print the newer lines */
     walk = logbuffer + sizeof(i3_shmlog_header);
-    while (walk < (logbuffer + header->offset_next_write)) {
+    print_till_end();
-        chars = printf("%s", walk);
+
-        walk += (chars > 0 ? chars : 1);
+    if (follow) {
+        /* Since pthread_cond_wait() expects a mutex, we need to provide one.
+         * To not lock i3 (that’s bad, mhkay?) we just define one outside of
+         * the shared memory. */
+        pthread_mutex_t dummy_mutex = PTHREAD_MUTEX_INITIALIZER;
+        pthread_mutex_lock(&dummy_mutex);
+        while (1) {
+            pthread_cond_wait(&(header->condvar), &dummy_mutex);
+            /* If this was not a spurious wakeup, print the new lines. */
+            if (header->offset_next_write != offset_next_write) {
+                offset_next_write = header->offset_next_write;
+                print_till_end();
+            }
+        }
     }
 
     return 0;

include/shmlog.h

@@ -12,11 +12,33 @@
 #define _I3_SHMLOG_H
 
 #include <stdint.h>
+#include <pthread.h>
 
+/*
+ * Header of the shmlog file. Used by i3/src/log.c and i3/i3-dump-log/main.c.
+ *
+ */
 typedef struct i3_shmlog_header {
+    /* Byte offset where the next line will be written to. */
     uint32_t offset_next_write;
+
+    /* Byte offset where the last wrap occured. */
     uint32_t offset_last_wrap;
+
+    /* The size of the logfile in bytes. Since the size is limited to 25 MiB
+     * an uint32_t is sufficient. */
     uint32_t size;
+
+    /* wrap counter. We need it to reliably signal to clients that we just
+     * wrapped (clients cannot use offset_last_wrap because that might
+     * coincidentally be exactly the same as previously). Overflows can happen
+     * and don’t matter — clients use an equality check (==). */
+    uint32_t wrap_count;
+
+    /* pthread condvar which will be broadcasted whenever there is a new
+     * message in the log. i3-dump-log uses this to implement -f (follow, like
+     * tail -f) in an efficient way. */
+    pthread_cond_t condvar;
 } i3_shmlog_header;
 
 #endif

src/i3.mk

@@ -7,7 +7,7 @@ i3_SOURCES           := $(filter-out $(i3_SOURCES_GENERATED),$(wildcard src/*.c)
 i3_HEADERS_CMDPARSER := $(wildcard include/GENERATED_*.h)
 i3_HEADERS           := $(filter-out $(i3_HEADERS_CMDPARSER),$(wildcard include/*.h))
 i3_CFLAGS             = $(XCB_CFLAGS) $(XCB_KBD_CFLAGS) $(XCB_WM_CFLAGS) $(X11_CFLAGS) $(XCURSOR_CFLAGS) $(YAJL_CFLAGS) $(LIBEV_CFLAGS) $(PCRE_CFLAGS) $(LIBSN_CFLAGS)
-i3_LIBS               = $(XCB_LIBS) $(XCB_KBD_LIBS) $(XCB_WM_LIBS) $(X11_LIBS) $(XCURSOR_LIBS) $(YAJL_LIBS) $(LIBEV_LIBS) $(PCRE_LIBS) $(LIBSN_LIBS) -lm
+i3_LIBS               = $(XCB_LIBS) $(XCB_KBD_LIBS) $(XCB_WM_LIBS) $(X11_LIBS) $(XCURSOR_LIBS) $(YAJL_LIBS) $(LIBEV_LIBS) $(PCRE_LIBS) $(LIBSN_LIBS) -lm -lpthread
 
 # When using clang, we use pre-compiled headers to speed up the build. With
 # gcc, this actually makes the build slower.

src/log.c

@@ -20,6 +20,7 @@
 #include <sys/mman.h>
 #include <sys/stat.h>
 #include <errno.h>
+#include <pthread.h>
 #if defined(__APPLE__)
 #include <sys/types.h>
 #include <sys/sysctl.h>
@@ -48,6 +49,8 @@ int shmlog_size = 0;
 static char *logbuffer;
 /* A pointer (within logbuffer) where data will be written to next. */
 static char *logwalk;
+/* A pointer to the shmlog header */
+static i3_shmlog_header *header;
 /* A pointer to the byte where we last wrapped. Necessary to not print the
  * left-overs at the end of the ringbuffer. */
 static char *loglastwrap;
@@ -63,8 +66,6 @@ static int logbuffer_shm;
  *
  */
 static void store_log_markers(void) {
-    i3_shmlog_header *header = (i3_shmlog_header*)logbuffer;
-
     header->offset_next_write = (logwalk - logbuffer);
     header->offset_last_wrap = (loglastwrap - logbuffer);
     header->size = logbuffer_size;
@@ -128,6 +129,18 @@ void init_logging(void) {
             logbuffer = NULL;
             return;
         }
+
+        /* Initialize with 0-bytes, just to be sure… */
+        memset(logbuffer, '\0', logbuffer_size);
+
+        header = (i3_shmlog_header*)logbuffer;
+
+        pthread_condattr_t cond_attr;
+        pthread_condattr_init(&cond_attr);
+        if (pthread_condattr_setpshared(&cond_attr, PTHREAD_PROCESS_SHARED) != 0)
+            ELOG("pthread_condattr_setpshared() failed, i3-dump-log -f will not work!\n");
+        pthread_cond_init(&(header->condvar), &cond_attr);
+
         logwalk = logbuffer + sizeof(i3_shmlog_header);
         loglastwrap = logbuffer + logbuffer_size;
         store_log_markers();
@@ -199,22 +212,25 @@ static void vlog(const bool print, const char *fmt, va_list args) {
             fprintf(stderr, "BUG: single log message > 4k\n");
         }
 
-        /* If there is no space for the current message (plus trailing
+        /* If there is no space for the current message in the ringbuffer, we
-         * nullbyte) in the ringbuffer, we need to wrap and write to the
+         * need to wrap and write to the beginning again. */
-         * beginning again. */
+        if (len >= (logbuffer_size - (logwalk - logbuffer))) {
-        if ((len+1) >= (logbuffer_size - (logwalk - logbuffer))) {
             loglastwrap = logwalk;
             logwalk = logbuffer + sizeof(i3_shmlog_header);
+            store_log_markers();
+            header->wrap_count++;
         }
 
-        /* Copy the buffer, terminate it, move the write pointer to the byte after
+        /* Copy the buffer, move the write pointer to the byte after our
-         * our current message. */
+         * current message. */
         strncpy(logwalk, message, len);
-        logwalk[len] = '\0';
+        logwalk += len;
-        logwalk += len + 1;
 
         store_log_markers();
 
+        /* Wake up all (i3-dump-log) processes waiting for condvar. */
+        pthread_cond_broadcast(&(header->condvar));
+
         if (print)
             fwrite(message, len, 1, stdout);
     }