Add logging of actual read/written data

   * With PK_LOG_TRACE, log first 64 bytes of all reads/writes
   * With PK_LOG_TUNNEL_DATA, log first 100 bytes of unparsable frames

libpagekite/pkconn.c

@@ -247,6 +247,11 @@ ssize_t pkc_read(struct pk_conn* pkc)
   }
 
   if (bytes > 0) {
+    if (pk_state.log_mask & PK_LOG_TRACE) {
+      pk_log_raw_data(PK_LOG_TRACE,
+                      "R", PKC_IN(*pkc), (bytes > 64) ? 64 : bytes);
+    }
+
     pkc->in_buffer_pos += bytes;
     pkc->activity = time(0);
 
@@ -342,7 +347,13 @@ ssize_t pkc_raw_write(struct pk_conn* pkc, char* data, ssize_t length) {
       if (length)
         wrote = PKS_write(pkc->sockfd, data, length);
   }
-  if (wrote > 0) pkc->wrote_bytes += wrote;
+  if (wrote > 0) {
+    if (pk_state.log_mask & PK_LOG_TRACE) {
+      pk_log_raw_data(PK_LOG_TRACE,
+                      "W", data, (wrote > 64) ? 64 : wrote);
+    }
+    pkc->wrote_bytes += wrote;
+  }
   return wrote;
 }
 

libpagekite/pklogging.c

@@ -112,6 +112,17 @@ int pk_log(int level, const char* fmt, ...)
   return r;
 }
 
+void pk_log_raw_data(int level, char* prefix, void* data, size_t bytes) {
+  char buffer[160];
+  int printed = 0;
+  char* p = (char *) data;
+
+  while (printed < bytes) {
+    printed += printable_binary(buffer, 160, p + printed, bytes - printed);
+    pk_log(level, "%s: %s", prefix, buffer);
+  }
+}
+
 int pk_log_chunk(struct pk_tunnel* fe, struct pk_chunk* chnk) {
   int i;
   int r = 0;

libpagekite/pklogging.h

@@ -28,6 +28,7 @@ Note: For alternate license terms, see the file COPYING.md.
 
 int pk_log(int, const char *fmt, ...);
 int pk_log_chunk(struct pk_tunnel*, struct pk_chunk*);
+void pk_log_raw_data(int, char*, void*, size_t);
 void pk_dump_parser(char*, struct pk_parser*);
 void pk_dump_conn(char*, struct pk_conn*);
 void pk_dump_tunnel(char*, struct pk_tunnel*);

libpagekite/pkmanager.c

@@ -607,6 +607,7 @@ static void pkm_tunnel_readable_cb(EV_P_ ev_io *w, int revents)
   int rv;
   struct pk_tunnel* fe = (struct pk_tunnel*) w->data;
   PK_TRACE_FUNCTION;
+
   fe->conn.status &= ~CONN_STATUS_WANT_READ;
   if (0 < pkc_read(&(fe->conn))) {
     if (0 > (rv = pk_parser_parse(fe->parser,
@@ -618,6 +619,11 @@ static void pkm_tunnel_readable_cb(EV_P_ ev_io *w, int revents)
       pk_log(PK_LOG_TUNNEL_HEADERS,
              "pkm_tunnel_readable_cb(): parse error = %d", rv);
       pk_dump_state(fe->manager);
+      if (pk_state.log_mask & PK_LOG_TUNNEL_DATA) {
+        int bytes = fe->conn.in_buffer_pos;
+        if (bytes > 100) bytes = 100;
+        pk_log_raw_data(PK_LOG_TUNNEL_DATA, "data", fe->conn.in_buffer, bytes);
+      }
     }
     fe->conn.in_buffer_pos = 0;
   }

libpagekite/pkutils.c

@@ -428,6 +428,48 @@ void digest_to_hex(const unsigned char* digest, char *output)
     *c = '\0';
 }
 
+int printable_binary(char* dest, size_t dlen, const char* src, size_t slen)
+{
+  char* p = (char *) src;
+  int copied = 0;
+  while (slen > copied) {
+    if (*p == '\0') {
+      /* Ensure we have space for two bytes plus null */
+      if (dlen < 3) {
+        *dest++ = '\0';
+        return copied;
+      }
+      *dest++ = '\\';
+      *dest++ = '0';
+      dlen -= 2;
+    }
+    else if (isgraph(*p) || (*p == ' ')) {
+      /* Ensure we have space for one byte plus null */
+      if (dlen < 2) {
+        *dest++ = '\0';
+        return copied;
+      }
+      *dest++ = *p;
+      dlen--;
+    }
+    else {
+      /* Ensure we have space for four bytes plus null */
+      if (dlen < 5) {
+        *dest++ = '\0';
+        return copied;
+      }
+      int wrote = sprintf(dest, "\\x%2.2x", *p);
+      dest += wrote;
+      dlen -= wrote;
+    }
+    copied++;
+    p++;
+  }
+
+  *dest++ = '\0';
+  return copied;
+}
+
 void pk_rlock_init(pk_rlock_t* rlock)
 {
   rlock->count = 0;
@@ -546,6 +588,7 @@ void init_memory_canaries() {
 int utils_test(void)
 {
 #if PK_TESTS
+  char binary[] = {'b', 'i', 'n', '\r', '\n', 0};
   char* haystack[] = {"b", "c", "d"};
   char buffer1[60];
   PK_MEMORY_CANARY;
@@ -568,6 +611,13 @@ int utils_test(void)
   assert(2 == strcaseindex((char**) haystack, "cC", 3));
   assert(3 == strcaseindex((char**) haystack, "E", 3));
 
+  assert(printable_binary(buffer1, 7, binary, 6) == 3);
+  assert(strcasecmp(buffer1, "bin") == 0);
+  assert(printable_binary(buffer1, 8, binary, 6) == 4);
+  assert(strcasecmp(buffer1, "bin\\x0d") == 0);
+  assert(printable_binary(buffer1, 60, binary, 6) == 6);
+  assert(strcasecmp(buffer1, "bin\\x0d\\x0a\\0") == 0);
+
 #if PK_MEMORY_CANARIES
   add_memory_canary(&canary);
   PK_CHECK_MEMORY_CANARIES;

libpagekite/pkutils.h

@@ -40,6 +40,7 @@ char* in_addr_to_str(const struct sockaddr*, char*, size_t);
 int addrcmp(const struct sockaddr *, const struct sockaddr *);
 int http_get(const char*, char*, size_t);
 void digest_to_hex(const unsigned char* digest, char *output);
+int printable_binary(char*, size_t, const char*, size_t);
 void pk_rlock_init(pk_rlock_t*);
 void pk_rlock_lock(pk_rlock_t*);
 void pk_rlock_unlock(pk_rlock_t*);