From c46b85ab7adb5b93924abe04b09c840a11dd7326 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Wed, 12 May 2021 22:10:30 -0700
Subject: [PATCH 01/28] First attempt at fixing the websocket test

---
 tests/Makefile    |   2 +-
 tests/websocket.c | 631 ++++++++++++++++++++++++++--------------------
 2 files changed, 356 insertions(+), 277 deletions(-)

diff --git a/tests/Makefile b/tests/Makefile
index a0b8a11..f382c4e 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -1,6 +1,6 @@
 OUT=websocket pubsub
 CFLAGS=-O3 -Wall -Wextra
-LDFLAGS=-levent -lpthread -lrt
+LDFLAGS=-levent -lpthread
 
 all: $(OUT) Makefile
 
diff --git a/tests/websocket.c b/tests/websocket.c
index 1b23ed8..39cb492 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -1,4 +1,4 @@
-/* http://tools.ietf.org/html/draft-hixie-thewebsocketprotocol-76 */
+/* https://datatracker.ietf.org/doc/html/rfc6455 */
 
 #include <stdlib.h>
 #define _GNU_SOURCE
@@ -15,312 +15,391 @@
 #include <event.h>
 
 struct host_info {
-	char *host;
-	short port;
+    char *host;
+    short port;
+};
+
+enum worker_state {
+    WS_INITIAL,
+    WS_SENT_HANDSHAKE,
+    WS_RECEIVED_RESPONSE,
+    WS_COMPLETE
 };
 
 /* worker_thread, with counter of remaining messages */
 struct worker_thread {
-	struct host_info *hi;
-	struct event_base *base;
+    struct host_info *hi;
+    struct event_base *base;
 
-	int msg_target;
-	int msg_received;
-	int msg_sent;
-	int byte_count;
-	pthread_t thread;
+    int msg_target;
+    int msg_received;
+    int msg_sent;
+    int byte_count;
+    pthread_t thread;
+    enum worker_state state;
 
-	struct evbuffer *buffer;
-	int got_header;
+    struct evbuffer *rbuffer;
+    int got_header;
 
-	int verbose;
-	struct event ev_w;
+    struct evbuffer *wbuffer;
+
+    int verbose;
+    int fd;
+    struct event ev_r;
+    struct event ev_w;
 };
 
+static void
+wait_for_possible_read(struct worker_thread *wt);
+static void
+wait_for_possible_write(struct worker_thread *wt);
+
 void
 process_message(struct worker_thread *wt, size_t sz) {
 
-	// printf("process_message\n");
-	if(wt->msg_received % 10000 == 0) {
-		printf("thread %u: %8d messages left (got %9d bytes so far).\n",
-			(unsigned int)wt->thread,
-			wt->msg_target - wt->msg_received, wt->byte_count);
-	}
-	wt->byte_count += sz;
-
-	/* decrement read count, and stop receiving when we reach zero. */
-	wt->msg_received++;
-	if(wt->msg_received == wt->msg_target) {
-		event_base_loopexit(wt->base, NULL);
-	}
+    // printf("process_message\n");
+    if(wt->msg_received % 10000 == 0) {
+        printf("thread %u: %8d messages left (got %9d bytes so far).\n",
+            (unsigned int)wt->thread,
+            wt->msg_target - wt->msg_received, wt->byte_count);
+    }
+    wt->byte_count += sz;
+
+    /* decrement read count, and stop receiving when we reach zero. */
+    wt->msg_received++;
+    if(wt->msg_received == wt->msg_target) {
+        event_base_loopexit(wt->base, NULL);
+    }
 }
 
+/**
+ * Called when we can write to the socket.
+ */
 void
-websocket_write(int fd, short event, void *ptr) {
-	int ret;
-	struct worker_thread *wt = ptr;
-
-	if(event != EV_WRITE) {
-		return;
-	}
-
-	char message[] = "\x00[\"SET\",\"key\",\"value\"]\xff\x00[\"GET\",\"key\"]\xff";
-	ret = write(fd, message, sizeof(message)-1);
-	if(ret != sizeof(message)-1) {
-		fprintf(stderr, "write on %d failed: %s\n", fd, strerror(errno));
-		close(fd);
-	}
-
-	wt->msg_sent += 2;
-	if(wt->msg_sent < wt->msg_target) {
-		event_set(&wt->ev_w, fd, EV_WRITE, websocket_write, wt);
-		event_base_set(wt->base, &wt->ev_w);
-		ret = event_add(&wt->ev_w, NULL);
-	}
+websocket_can_write(int fd, short event, void *ptr) {
+    int ret;
+    struct worker_thread *wt = ptr;
+    printf("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
+
+    if(event != EV_WRITE) {
+        return;
+    }
+    switch (wt->state)
+    {
+    case WS_INITIAL: /* still sending initial HTTP request */
+        ret = evbuffer_write(wt->wbuffer, fd);
+        printf("evbuffer_write returned %d\n", ret);
+        printf("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
+        if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */ 
+            wait_for_possible_write(wt);
+            return;
+        }
+        /* otherwise, we've sent the full request, time to read the response */
+        wt->state = WS_SENT_HANDSHAKE;
+        wait_for_possible_read(wt);
+        return;
+
+    default:
+        break;
+    }
+#if 0
+    char message[] = "\x00[\"SET\",\"key\",\"value\"]\xff\x00[\"GET\",\"key\"]\xff";
+    ret = write(fd, message, sizeof(message)-1);
+    if(ret != sizeof(message)-1) {
+        fprintf(stderr, "write on %d failed: %s\n", fd, strerror(errno));
+        close(fd);
+    }
+
+    wt->msg_sent += 2;
+    if(wt->msg_sent < wt->msg_target) {
+        event_set(&wt->ev_w, fd, EV_WRITE, websocket_can_write, wt);
+        event_base_set(wt->base, &wt->ev_w);
+        ret = event_add(&wt->ev_w, NULL);
+    }
+#endif
+}
+
+static void
+websocket_can_read(int fd, short event, void *ptr) {
+    char packet[2048], *pos;
+    int ret, success = 1;
+
+    struct worker_thread *wt = ptr;
+    printf("%s (wt=%p)\n", __func__, wt);
+
+    if(event != EV_READ) {
+        return;
+    }
+
+    /* read message */
+    ret = evbuffer_read(wt->rbuffer, fd, 65536);
+    printf("evbuffer_read() returned %d\n", ret);
+    
+
+#if 0
+    pos = packet;
+    if(ret > 0) {
+        char *data, *last;
+        int sz, msg_sz;
+
+        if(wt->got_header == 0) { /* first response */
+            char *frame_start = strstr(packet, "MH"); /* end of the handshake */
+            if(frame_start == NULL) {
+                return; /* not yet */
+            } else { /* start monitoring possible writes */
+                printf("start monitoring possible writes\n");
+                evbuffer_add(wt->rbuffer, frame_start + 2, ret - (frame_start + 2 - packet));
+
+                wt->got_header = 1;
+                event_set(&wt->ev_w, fd, EV_WRITE,
+                        websocket_can_write, wt);
+                event_base_set(wt->base, &wt->ev_w);
+                ret = event_add(&wt->ev_w, NULL);
+            }
+        } else {
+            /* we've had the header already, now bufffer data. */
+            evbuffer_add(wt->rbuffer, packet, ret);
+        }
+
+        while(1) {
+            data = (char*)EVBUFFER_DATA(wt->rbuffer);
+            sz = EVBUFFER_LENGTH(wt->rbuffer);
+
+            if(sz == 0) { /* no data */
+                break;
+            }
+            if(*data != 0) { /* missing frame start */
+                success = 0;
+                break;
+            }
+            last = memchr(data, 0xff, sz); /* look for frame end */
+            if(!last) {
+                /* no end of frame in sight. */
+                break;
+            }
+            msg_sz = last - data - 1;
+            process_message(ptr, msg_sz); /* record packet */
+
+            /* drain including frame delimiters (+2 bytes) */
+            evbuffer_drain(wt->rbuffer, msg_sz + 2); 
+        }
+    } else {
+        printf("ret=%d\n", ret);
+        success = 0;
+    }
+    if(success == 0) {
+        shutdown(fd, SHUT_RDWR);
+        close(fd);
+        event_base_loopexit(wt->base, NULL);
+    }
+    #endif
+}
+
+
+static void
+wait_for_possible_read(struct worker_thread *wt) {
+    printf("%s (wt=%p)\n", __func__, wt);
+    event_set(&wt->ev_r, wt->fd, EV_READ, websocket_can_read, wt);
+    event_base_set(wt->base, &wt->ev_r);
+    event_add(&wt->ev_r, NULL);
 }
 
 static void
-websocket_read(int fd, short event, void *ptr) {
-	char packet[2048], *pos;
-	int ret, success = 1;
-
-	struct worker_thread *wt = ptr;
-
-	if(event != EV_READ) {
-		return;
-	}
-
-	/* read message */
-	ret = read(fd, packet, sizeof(packet));
-	pos = packet;
-	if(ret > 0) {
-		char *data, *last;
-		int sz, msg_sz;
-
-		if(wt->got_header == 0) { /* first response */
-			char *frame_start = strstr(packet, "MH"); /* end of the handshake */
-			if(frame_start == NULL) {
-				return; /* not yet */
-			} else { /* start monitoring possible writes */
-				printf("start monitoring possible writes\n");
-				evbuffer_add(wt->buffer, frame_start + 2, ret - (frame_start + 2 - packet));
-
-				wt->got_header = 1;
-				event_set(&wt->ev_w, fd, EV_WRITE,
-						websocket_write, wt);
-				event_base_set(wt->base, &wt->ev_w);
-				ret = event_add(&wt->ev_w, NULL);
-			}
-		} else {
-			/* we've had the header already, now bufffer data. */
-			evbuffer_add(wt->buffer, packet, ret);
-		}
-
-		while(1) {
-			data = (char*)EVBUFFER_DATA(wt->buffer);
-			sz = EVBUFFER_LENGTH(wt->buffer);
-
-			if(sz == 0) { /* no data */
-				break;
-			}
-			if(*data != 0) { /* missing frame start */
-				success = 0;
-				break;
-			}
-			last = memchr(data, 0xff, sz); /* look for frame end */
-			if(!last) {
-				/* no end of frame in sight. */
-				break;
-			}
-			msg_sz = last - data - 1;
-			process_message(ptr, msg_sz); /* record packet */
-
-			/* drain including frame delimiters (+2 bytes) */
-			evbuffer_drain(wt->buffer, msg_sz + 2); 
-		}
-	} else {
-		printf("ret=%d\n", ret);
-		success = 0;
-	}
-	if(success == 0) {
-		shutdown(fd, SHUT_RDWR);
-		close(fd);
-		event_base_loopexit(wt->base, NULL);
-	}
+wait_for_possible_write(struct worker_thread *wt) {
+    printf("%s (wt=%p)\n", __func__, wt);
+    event_set(&wt->ev_r, wt->fd, EV_WRITE, websocket_can_write, wt);
+    event_base_set(wt->base, &wt->ev_r);
+    event_add(&wt->ev_r, NULL);
 }
 
 void*
 worker_main(void *ptr) {
 
-	char ws_template[] = "GET /.json HTTP/1.1\r\n"
-				"Host: %s:%d\r\n"
-				"Connection: Upgrade\r\n"
-				"Upgrade: WebSocket\r\n"
-				"Origin: http://%s:%d\r\n"
-				"Sec-WebSocket-Key1: 18x 6]8vM;54 *(5:  {   U1]8  z [  8\r\n"
-				"Sec-WebSocket-Key2: 1_ tx7X d  <  nw  334J702) 7]o}` 0\r\n"
-				"\r\n"
-				"Tm[K T2u";
-
-	struct worker_thread *wt = ptr;
-
-	int ret;
-	int fd;
-	struct sockaddr_in addr;
-	char *ws_handshake;
-	size_t ws_handshake_sz;
-
-	/* connect socket */
-	fd = socket(AF_INET, SOCK_STREAM, 0);
-	addr.sin_family = AF_INET;
-	addr.sin_port = htons(wt->hi->port);
-	memset(&(addr.sin_addr), 0, sizeof(addr.sin_addr));
-	addr.sin_addr.s_addr = inet_addr(wt->hi->host);
-
-	ret = connect(fd, (struct sockaddr*)&addr, sizeof(struct sockaddr));
-	if(ret != 0) {
-		fprintf(stderr, "connect: ret=%d: %s\n", ret, strerror(errno));
-		return NULL;
-	}
-
-	/* initialize worker thread */
-	wt->base = event_base_new();
-	wt->buffer = evbuffer_new();
-	wt->byte_count = 0;
-	wt->got_header = 0;
-
-	/* send handshake */
-	ws_handshake_sz = sizeof(ws_handshake)
-		+ 2*strlen(wt->hi->host) + 500;
-	ws_handshake = calloc(ws_handshake_sz, 1);
-	ws_handshake_sz = (size_t)sprintf(ws_handshake, ws_template, 
-			wt->hi->host, wt->hi->port,
-			wt->hi->host, wt->hi->port);
-	ret = write(fd, ws_handshake, ws_handshake_sz);
-
-	struct event ev_r;
-	event_set(&ev_r, fd, EV_READ | EV_PERSIST, websocket_read, wt);
-	event_base_set(wt->base, &ev_r);
-	event_add(&ev_r, NULL);
-
-	/* go! */
-	event_base_dispatch(wt->base);
-	event_base_free(wt->base);
-	free(ws_handshake);
-	return NULL;
+    char ws_template[] = "GET /.json HTTP/1.1\r\n"
+                "Host: %s:%d\r\n"
+                "Connection: Upgrade\r\n"
+                "Upgrade: WebSocket\r\n"
+                "Origin: http://%s:%d\r\n"
+                "Sec-WebSocket-Key: webdis-websocket-test-key\r\n"
+                "\r\n"
+                ;
+
+    struct worker_thread *wt = ptr;
+
+    int ret;
+    int fd;
+    struct sockaddr_in addr;
+    char *ws_handshake;
+    size_t ws_handshake_sz;
+
+    /* connect socket */
+    fd = socket(AF_INET, SOCK_STREAM, 0);
+    addr.sin_family = AF_INET;
+    addr.sin_port = htons(wt->hi->port);
+    memset(&(addr.sin_addr), 0, sizeof(addr.sin_addr));
+    addr.sin_addr.s_addr = inet_addr(wt->hi->host);
+
+    ret = connect(fd, (struct sockaddr*)&addr, sizeof(struct sockaddr));
+    if(ret != 0) {
+        fprintf(stderr, "connect: ret=%d: %s\n", ret, strerror(errno));
+        return NULL;
+    }
+
+    /* initialize worker thread */
+    wt->fd = fd;
+    wt->base = event_base_new();
+    wt->rbuffer = evbuffer_new();
+    wt->wbuffer = evbuffer_new(); /* write buffer */
+    wt->byte_count = 0;
+    wt->got_header = 0;
+
+    /* build handshake buffer */
+    /*
+    ws_handshake_sz = sizeof(ws_handshake)
+        + 2*strlen(wt->hi->host) + 500;
+    ws_handshake = calloc(ws_handshake_sz, 1);
+    ws_handshake_sz = (size_t)sprintf(ws_handshake, ws_template, 
+            wt->hi->host, wt->hi->port,
+            wt->hi->host, wt->hi->port);
+    */
+    int added = evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
+                                    wt->hi->host, wt->hi->port);
+    wait_for_possible_write(wt); /* request callback */
+
+    /* go! */
+    event_base_dispatch(wt->base);
+    printf("event_base_dispatch returned\n");
+    event_base_free(wt->base);
+    free(ws_handshake);
+    return NULL;
 }
 
 void
 usage(const char* argv0, char *host_default, short port_default,
-		int thread_count_default, int messages_default) {
-
-	printf("Usage: %s [options]\n"
-		"Options are:\n"
-		"\t-h host\t\t(default = \"%s\")\n"
-		"\t-p port\t\t(default = %d)\n"
-		"\t-c threads\t(default = %d)\n"
-		"\t-n count\t(number of messages per thread, default = %d)\n"
-		"\t-v\t\t(verbose)\n",
-		argv0, host_default, (int)port_default,
-		thread_count_default, messages_default);
+        int thread_count_default, int messages_default) {
+
+    printf("Usage: %s [options]\n"
+        "Options are:\n"
+        "\t-h host\t\t(default = \"%s\")\n"
+        "\t-p port\t\t(default = %d)\n"
+        "\t-c threads\t(default = %d)\n"
+        "\t-n count\t(number of messages per thread, default = %d)\n"
+        "\t-v\t\t(verbose)\n",
+        argv0, host_default, (int)port_default,
+        thread_count_default, messages_default);
 }
 
 int
 main(int argc, char *argv[]) {
 
-	struct timespec t0, t1;
-
-	int messages_default = 100000;
-	int thread_count_default = 4;
-	short port_default = 7379;
-	char *host_default = "127.0.0.1";
-
-	int msg_target = messages_default;
-	int thread_count = thread_count_default;
-	int i, opt;
-	char *colon;
-	double total = 0, total_bytes = 0;
-	int verbose = 0;
-
-	struct host_info hi = {host_default, port_default};
-
-	struct worker_thread *workers;
-
-	/* getopt */
-	while ((opt = getopt(argc, argv, "h:p:c:n:v")) != -1) {
-		switch (opt) {
-			case 'h':
-				colon = strchr(optarg, ':');
-				if(!colon) {
-					size_t sz = strlen(optarg);
-					hi.host = calloc(1 + sz, 1);
-					strncpy(hi.host, optarg, sz);
-				} else {
-					hi.host = calloc(1+colon-optarg, 1);
-					strncpy(hi.host, optarg, colon-optarg);
-					hi.port = (short)atol(colon+1);
-				}
-				break;
-
-			case 'p':
-				hi.port = (short)atol(optarg);
-				break;
-
-			case 'c':
-				thread_count = atoi(optarg);
-				break;
-
-			case 'n':
-				msg_target = atoi(optarg);
-				break;
-
-			case 'v':
-				verbose = 1;
-				break;
-			default: /* '?' */
-				usage(argv[0], host_default, port_default,
-						thread_count_default,
-						messages_default);
-				exit(EXIT_FAILURE);
-		}
-	}
-
-	/* run threads */
-	workers = calloc(sizeof(struct worker_thread), thread_count);
-
-	clock_gettime(CLOCK_MONOTONIC, &t0);
-	for(i = 0; i < thread_count; ++i) {
-		workers[i].msg_target = msg_target;
-		workers[i].hi = &hi;
-		workers[i].verbose = verbose;
-
-		pthread_create(&workers[i].thread, NULL,
-				worker_main, &workers[i]);
-	}
-
-	/* wait for threads to finish */
-	for(i = 0; i < thread_count; ++i) {
-		pthread_join(workers[i].thread, NULL);
-		total += workers[i].msg_received;
-		total_bytes += workers[i].byte_count;
-	}
-
-	/* timing */
-	clock_gettime(CLOCK_MONOTONIC, &t1);
-	float mili0 = t0.tv_sec * 1000 + t0.tv_nsec / 1000000;
-	float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
-
-	if(total != 0) {
-		printf("Read %ld messages in %0.2f sec: %0.2f msg/sec (%d MB/sec, %d KB/sec)\n",
-			(long)total, 
-			(mili1-mili0)/1000.0,
-			1000*total/(mili1-mili0),
-			(int)(total_bytes / (1000*(mili1-mili0))),
-			(int)(total_bytes / (mili1-mili0)));
-		return EXIT_SUCCESS;
-	} else {
-		printf("No message was read.\n");
-		return EXIT_FAILURE;
-	}
+    struct timespec t0, t1;
+
+    int messages_default = 100000;
+    int thread_count_default = 4;
+    short port_default = 7379;
+    char *host_default = "127.0.0.1";
+
+    int msg_target = messages_default;
+    int thread_count = thread_count_default;
+    int i, opt;
+    char *colon;
+    double total = 0, total_bytes = 0;
+    int verbose = 0, single = 0;
+
+    struct host_info hi = {host_default, port_default};
+
+    struct worker_thread *workers;
+
+    /* getopt */
+    while ((opt = getopt(argc, argv, "h:p:c:n:vs")) != -1) {
+        switch (opt) {
+            case 'h':
+                colon = strchr(optarg, ':');
+                if(!colon) {
+                    size_t sz = strlen(optarg);
+                    hi.host = calloc(1 + sz, 1);
+                    strncpy(hi.host, optarg, sz);
+                } else {
+                    hi.host = calloc(1+colon-optarg, 1);
+                    strncpy(hi.host, optarg, colon-optarg);
+                    hi.port = (short)atol(colon+1);
+                }
+                break;
+
+            case 'p':
+                hi.port = (short)atol(optarg);
+                break;
+
+            case 'c':
+                thread_count = atoi(optarg);
+                break;
+
+            case 'n':
+                msg_target = atoi(optarg);
+                break;
+
+            case 'v':
+                verbose = 1;
+                break;
+
+            case 's':
+                single = 1;
+                thread_count = 1;
+                break;
+            default: /* '?' */
+                usage(argv[0], host_default, port_default,
+                        thread_count_default,
+                        messages_default);
+                exit(EXIT_FAILURE);
+        }
+    }
+
+    /* run threads */
+    workers = calloc(sizeof(struct worker_thread), thread_count);
+
+    clock_gettime(CLOCK_MONOTONIC, &t0);
+    if (single) {
+        printf("Single-threaded mode\n");
+        workers[0].msg_target = msg_target;
+        workers[0].hi = &hi;
+        workers[0].verbose = verbose;
+        workers[0].state = WS_INITIAL;
+        worker_main(&workers[0]);
+    } else {
+        for (i = 0; i < thread_count; ++i) {
+            workers[i].msg_target = msg_target;
+            workers[i].hi = &hi;
+            workers[i].verbose = verbose;
+            workers[i].state = WS_INITIAL;
+
+            pthread_create(&workers[i].thread, NULL,
+                           worker_main, &workers[i]);
+        }
+
+        /* wait for threads to finish */
+        for (i = 0; i < thread_count; ++i) {
+            pthread_join(workers[i].thread, NULL);
+            total += workers[i].msg_received;
+            total_bytes += workers[i].byte_count;
+        }
+    }
+
+    /* timing */
+    clock_gettime(CLOCK_MONOTONIC, &t1);
+    float mili0 = t0.tv_sec * 1000 + t0.tv_nsec / 1000000;
+    float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
+
+    if(total != 0) {
+        printf("Read %ld messages in %0.2f sec: %0.2f msg/sec (%d MB/sec, %d KB/sec)\n",
+            (long)total, 
+            (mili1-mili0)/1000.0,
+            1000*total/(mili1-mili0),
+            (int)(total_bytes / (1000*(mili1-mili0))),
+            (int)(total_bytes / (mili1-mili0)));
+        return EXIT_SUCCESS;
+    } else {
+        printf("No message was read.\n");
+        return EXIT_FAILURE;
+    }
 }
 

From 0a27fc7e106c92fe105289fbb8c0aea38b52897e Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Thu, 13 May 2021 16:35:23 -0700
Subject: [PATCH 02/28] More progress on evbuffer-based WS client test

---
 src/http.c        |   3 +
 src/websocket.c   |  16 ++-
 src/worker.c      |   4 +-
 tests/Makefile    |   8 +-
 tests/websocket.c | 264 ++++++++++++++++++++++++++++++++++++++++++++--
 5 files changed, 276 insertions(+), 19 deletions(-)

diff --git a/src/http.c b/src/http.c
index ef4ea9a..6b7acd2 100644
--- a/src/http.c
+++ b/src/http.c
@@ -98,6 +98,7 @@ http_response_cleanup(struct http_response *r, int fd, int success) {
 	free(r->out);
 	if(!r->keep_alive || !success) {
 		/* Close fd is client doesn't support Keep-Alive. */
+		fprintf(stderr, "http_response_cleanup: keep_alive=%d, success=%d -> closing\n", r->keep_alive, success);
 		close(fd);
 	}
 
@@ -124,6 +125,8 @@ http_can_write(int fd, short event, void *p) {
 	if(ret > 0)
 		r->sent += ret;
 
+	fprintf(stderr, "http_can_write: ret=%d, r->out_sz=%lu, r->sent=%d\n",
+		ret, r->out_sz, r->sent);
 	if(ret <= 0 || r->out_sz - r->sent == 0) { /* error or done */
 		http_response_cleanup(r, fd, (int)r->out_sz == r->sent ? 1 : 0);
 	} else { /* reschedule write */
diff --git a/src/websocket.c b/src/websocket.c
index 44ee6a6..687fbfe 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -220,6 +220,7 @@ ws_execute(struct http_client *c, const char *frame, size_t frame_len) {
 
 static struct ws_msg *
 ws_msg_new() {
+	fprintf(stderr, "------------ NEW -----------\n");
 	return calloc(1, sizeof(struct ws_msg));
 }
 
@@ -235,6 +236,7 @@ ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mas
 	for(i = 0; i < psz && mask; ++i) {
 		m->payload[m->payload_sz + i] = (unsigned char)p[i] ^ mask[i%4];
 	}
+	fprintf(stderr, "CONTENTS=[%.*s] (%lu)\n", (int)psz, m->payload, psz);
 
 	/* save new size */
 	m->payload_sz += psz;
@@ -242,7 +244,7 @@ ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mas
 
 static void
 ws_msg_free(struct ws_msg **m) {
-
+	fprintf(stderr, "------------ /FREE -----------\n");
 	free((*m)->payload);
 	free(*m);
 	*m = NULL;
@@ -262,12 +264,15 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
 	}
 
 	has_mask = frame[1] & 0x80 ? 1:0;
+	fprintf(stderr, "has_mask=%d\n", has_mask);
 
 	/* get payload length */
 	len = frame[1] & 0x7f;	/* remove leftmost bit */
+	fprintf(stderr, "len=%llu\n", len);
 	if(len <= 125) { /* data starts right after the mask */
 		p = frame + 2 + (has_mask ? 4 : 0);
 		if(has_mask) memcpy(&mask, frame + 2, sizeof(mask));
+		if (has_mask) fprintf(stderr, "mask= %02x %02x %02x %02x\n", mask[0], mask[1], mask[2], mask[3]);
 	} else if(len == 126) {
 		uint16_t sz16;
 		memcpy(&sz16, frame + 2, sizeof(uint16_t));
@@ -293,8 +298,10 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
 	(*msg)->total_sz += len + (p - frame);
 
 	if(frame[0] & 0x80) { /* FIN bit set */
+		fprintf(stderr, "FIN bit: SET\n");
 		return WS_MSG_COMPLETE;
 	} else {
+		fprintf(stderr, "FIN bit: NOT SET\n");
 		return WS_READING;	/* need more data */
 	}
 }
@@ -312,6 +319,7 @@ ws_add_data(struct http_client *c) {
 
 	while(state == WS_MSG_COMPLETE) {
 		int ret = ws_execute(c, c->frame->payload, c->frame->payload_sz);
+		fprintf(stderr, "ws_execute returned %d\n", ret);
 
 		/* remove frame from client buffer */
 		http_client_remove_data(c, c->frame->total_sz);
@@ -323,14 +331,16 @@ ws_add_data(struct http_client *c) {
 			/* can't process frame. */
 			return WS_ERROR;
 		}
+		fprintf(stderr, "Calling ws_parse_data again...\n");
 		state = ws_parse_data(c->buffer, c->sz, &c->frame);
+		fprintf(stderr, "ws_parse_data returned %d\n", (int)state);
 	}
 	return state;
 }
 
 int
 ws_reply(struct cmd *cmd, const char *p, size_t sz) {
-
+	fprintf(stderr, "ws_reply: '%.*s' (%lu bytes)\n", (int)sz, p, sz);
 	char *frame = malloc(sz + 8); /* create frame by prepending header */
 	size_t frame_sz = 0;
 	struct http_response *r;
@@ -365,7 +375,7 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) {
 
 	/* send WS frame */
 	r = http_response_init(cmd->w, 0, NULL);
-	if (cmd_is_subscribe(cmd)) {
+	if (1 || cmd_is_subscribe(cmd)) {
 		r->keep_alive = 1;
 	}
 
diff --git a/src/worker.c b/src/worker.c
index d5decef..1d5b838 100644
--- a/src/worker.c
+++ b/src/worker.c
@@ -35,7 +35,7 @@ worker_new(struct server *s) {
 
 void
 worker_can_read(int fd, short event, void *p) {
-
+	fprintf(stderr, "worker_can_read\n");
 	struct http_client *c = p;
 	int ret, nparsed;
 
@@ -87,9 +87,11 @@ worker_can_read(int fd, short event, void *p) {
 	}
 
 	if(c->broken) { /* terminate client */
+		fprintf(stderr, "c->broken: http_client_free()\n");
 		http_client_free(c);
 	} else {
 		/* start monitoring input again */
+		fprintf(stderr, "worker_monitor_input()\n");
 		worker_monitor_input(c);
 	}
 }
diff --git a/tests/Makefile b/tests/Makefile
index f382c4e..be3caa0 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -1,11 +1,11 @@
 OUT=websocket pubsub
-CFLAGS=-O3 -Wall -Wextra
-LDFLAGS=-levent -lpthread
+CFLAGS=-O0 -g -Wall -Wextra -I../src/http-parser/
+LDFLAGS=-g -levent -lpthread
 
 all: $(OUT) Makefile
 
-websocket: websocket.o
-	$(CC) -o $@ $< $(LDFLAGS)
+websocket: websocket.o ../src/http-parser/http_parser.o
+	$(CC) -o $@ $^ $(LDFLAGS)
 
 pubsub: pubsub.o
 	$(CC) -o $@ $< $(LDFLAGS)
diff --git a/tests/websocket.c b/tests/websocket.c
index 39cb492..3c53cb1 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -8,11 +8,15 @@
 #include <pthread.h>
 #include <arpa/inet.h>
 #include <errno.h>
+#include <ctype.h>
 
 #include <sys/types.h>
 #include <sys/socket.h>
 
 #include <event.h>
+#include <http_parser.h>
+
+#define DEBUG_LOGS 0
 
 struct host_info {
     char *host;
@@ -22,7 +26,8 @@ struct host_info {
 enum worker_state {
     WS_INITIAL,
     WS_SENT_HANDSHAKE,
-    WS_RECEIVED_RESPONSE,
+    WS_RECEIVED_HANDSHAKE,
+    WS_SENT_FRAME,
     WS_COMPLETE
 };
 
@@ -47,13 +52,49 @@ struct worker_thread {
     int fd;
     struct event ev_r;
     struct event ev_w;
+
+    http_parser parser;
+    http_parser_settings settings;
 };
 
+void
+hex_dump(char *p, size_t sz) {
+#if DEBUG_LOGS
+    printf("hex dump of %p (%ld bytes)\n", p, sz);
+    for (char *cur = p; cur < p + sz; cur += 16) {
+        char letters[16] = {0};
+        int limit = (cur + 16) > p + sz ? (sz % 16) : 16;
+        printf("%08lx ", cur - p); /* address */
+        for (int i = 0; i < limit; i++) {
+            printf("%02x ", (unsigned int)(cur[i] & 0xff));
+            letters[i] = isprint(cur[i]) ? cur[i] : '.';
+        }
+        for (int i = limit; i < 16; i++) { /* pad on last line */
+            printf("   ");
+        }
+        printf(" %.*s\n", limit, letters);
+    }
+#endif
+}
+
+void
+evbuffer_debug_dump(struct evbuffer *buffer) {
+    size_t sz = evbuffer_get_length(buffer);
+    char *data = malloc(sz);
+    evbuffer_remove(buffer, data, sz);
+    hex_dump(data, sz);
+    evbuffer_prepend(buffer, data, sz);
+    free(data);
+}
+
 static void
 wait_for_possible_read(struct worker_thread *wt);
 static void
 wait_for_possible_write(struct worker_thread *wt);
 
+static void
+ws_enqueue_frame(struct worker_thread *wt);
+
 void
 process_message(struct worker_thread *wt, size_t sz) {
 
@@ -79,26 +120,51 @@ void
 websocket_can_write(int fd, short event, void *ptr) {
     int ret;
     struct worker_thread *wt = ptr;
+#if DEBUG_LOGS
     printf("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
+#endif
 
     if(event != EV_WRITE) {
         return;
     }
     switch (wt->state)
     {
-    case WS_INITIAL: /* still sending initial HTTP request */
+    case WS_INITIAL: { /* still sending initial HTTP request */
         ret = evbuffer_write(wt->wbuffer, fd);
+#if DEBUG_LOGS
         printf("evbuffer_write returned %d\n", ret);
         printf("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
-        if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */ 
+#endif
+        if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */
             wait_for_possible_write(wt);
             return;
         }
         /* otherwise, we've sent the full request, time to read the response */
         wt->state = WS_SENT_HANDSHAKE;
+#if DEBUG_LOGS
+        printf("state=WS_SENT_HANDSHAKE\n");
+#endif
         wait_for_possible_read(wt);
         return;
-
+    }
+    case WS_RECEIVED_HANDSHAKE: { /* ready to send a frame */
+#if DEBUG_LOGS
+        printf("About to send data for WS frame, %lu in buffer\n", evbuffer_get_length(wt->wbuffer));
+#endif
+        evbuffer_write(wt->wbuffer, fd);
+        size_t write_remains = evbuffer_get_length(wt->wbuffer);
+#if DEBUG_LOGS
+        printf("Sent data for WS frame, still %lu left to write\n", write_remains);
+#endif
+        if (write_remains == 0) { /* ready to read response */
+            wt->state = WS_SENT_FRAME;
+            wt->msg_sent++;
+            wait_for_possible_read(wt);
+        } else { /* not finished writing */
+            wait_for_possible_write(wt);
+        }
+        return;
+    }
     default:
         break;
     }
@@ -125,7 +191,9 @@ websocket_can_read(int fd, short event, void *ptr) {
     int ret, success = 1;
 
     struct worker_thread *wt = ptr;
+#if DEBUG_LOGS
     printf("%s (wt=%p)\n", __func__, wt);
+#endif
 
     if(event != EV_READ) {
         return;
@@ -133,8 +201,113 @@ websocket_can_read(int fd, short event, void *ptr) {
 
     /* read message */
     ret = evbuffer_read(wt->rbuffer, fd, 65536);
-    printf("evbuffer_read() returned %d\n", ret);
-    
+#if DEBUG_LOGS
+    printf("evbuffer_read() returned %d; wt->state=%d. wt->rbuffer:\n", ret, wt->state);
+#endif
+    evbuffer_debug_dump(wt->rbuffer);
+    if (ret == 0) {
+#if DEBUG_LOGS
+        printf("We didn't read anything from the socket...\n");
+#endif
+        wait_for_possible_read(wt);
+        return;
+    }
+
+    while(1) {
+        switch (wt->state) {
+        case WS_SENT_HANDSHAKE: { /* waiting for handshake response */
+            size_t avail_sz = evbuffer_get_length(wt->rbuffer);
+            char *tmp = calloc(avail_sz, 1);
+#if DEBUG_LOGS
+            printf("avail_sz from rbuffer = %lu\n", avail_sz);
+#endif
+            evbuffer_remove(wt->rbuffer, tmp, avail_sz); /* copy into `tmp` */
+#if DEBUG_LOGS
+            printf("Giving %lu bytes to http-parser\n", avail_sz);
+#endif
+            int nparsed = http_parser_execute(&wt->parser, &wt->settings, tmp, avail_sz);
+#if DEBUG_LOGS
+            printf("http-parser returned %d\n", nparsed);
+#endif
+            if (nparsed != (int)avail_sz) { // put back what we didn't read
+#if DEBUG_LOGS
+                printf("re-attach (prepend) %lu bytes\n", avail_sz - nparsed);
+#endif
+                evbuffer_prepend(wt->rbuffer, tmp + nparsed, avail_sz - nparsed);
+            }
+            free(tmp);
+            if (wt->state == WS_SENT_HANDSHAKE &&  /* haven't encountered end of response yet */
+                wt->parser.upgrade && nparsed != (int)avail_sz) {
+#if DEBUG_LOGS
+                printf("UPGRADE *and* we have some data left\n");
+#endif
+                continue;
+            } else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
+                evbuffer_drain(wt->rbuffer, evbuffer_get_length(wt->rbuffer));
+            }
+        }
+        return;
+
+        case WS_SENT_FRAME: { /* waiting for frame response */
+#if DEBUG_LOGS
+            printf("We're in WS_SENT_FRAME, just read a frame response. wt->rbuffer:\n");
+#endif
+            evbuffer_debug_dump(wt->rbuffer);
+            uint8_t flag_opcodes, payload_len;
+            if (evbuffer_get_length(wt->rbuffer) < 2) { /* not enough data */
+                wait_for_possible_read(wt);
+                return;
+            }
+            evbuffer_remove(wt->rbuffer, &flag_opcodes, 1); /* remove flags & opcode */
+            evbuffer_remove(wt->rbuffer, &payload_len, 1);  /* remove length */
+            evbuffer_drain(wt->rbuffer, (size_t)payload_len); /* remove payload itself */
+            process_message(wt, payload_len);
+
+            if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything, let's write again */
+#if DEBUG_LOGS
+                printf("our turn to write again\n");
+#endif
+                wt->state = WS_RECEIVED_HANDSHAKE;
+                ws_enqueue_frame(wt);
+                return;
+            } else {
+#if DEBUG_LOGS
+                printf("there's still data to consume\n");
+#endif
+                continue;
+            }
+#if 0
+            struct evbuffer_ptr sof = evbuffer_search(wt->rbuffer, "\x00", 1, NULL);
+            struct evbuffer_ptr eof = evbuffer_search(wt->rbuffer, "\xff", 1, NULL);
+            if (evbuffer_get_length(wt->rbuffer) >= 1 && sof.pos != 0) {
+                printf("ERROR: length=%lu, sof at pos %ld\n", evbuffer_get_length(wt->rbuffer), sof.pos);
+            }
+            if (eof.pos == -1) { /* not there yet */
+                printf("Couldn't find the end-of-frame marker, need to read more\n");
+                wait_for_possible_read(wt);
+            } else { /* we have a frame */
+                size_t bounded_frame_sz = eof.pos + 1;
+                char *bounded_frame = calloc(bounded_frame_sz, 1);
+                evbuffer_remove(wt->rbuffer, bounded_frame, bounded_frame_sz);
+                process_message(wt, bounded_frame_sz);
+                printf("Received frame (%lu bytes total):\n", bounded_frame_sz);
+                hex_dump(bounded_frame, bounded_frame_sz);
+                free(bounded_frame);
+                if (evbuffer_get_length(wt->rbuffer) > 0) { /* we may have more frames to process */
+                    continue;
+                } else { /* our turn to send a frame */
+                    printf("Add frame to write buffer\n");
+                    ws_enqueue_frame(wt);
+                }
+            }
+#endif
+        }
+        return;
+
+        default:
+            return;
+        }
+    }
 
 #if 0
     pos = packet;
@@ -181,7 +354,7 @@ websocket_can_read(int fd, short event, void *ptr) {
             process_message(ptr, msg_sz); /* record packet */
 
             /* drain including frame delimiters (+2 bytes) */
-            evbuffer_drain(wt->rbuffer, msg_sz + 2); 
+            evbuffer_drain(wt->rbuffer, msg_sz + 2);
         }
     } else {
         printf("ret=%d\n", ret);
@@ -192,13 +365,15 @@ websocket_can_read(int fd, short event, void *ptr) {
         close(fd);
         event_base_loopexit(wt->base, NULL);
     }
-    #endif
+#endif
 }
 
 
 static void
 wait_for_possible_read(struct worker_thread *wt) {
+#if DEBUG_LOGS
     printf("%s (wt=%p)\n", __func__, wt);
+#endif
     event_set(&wt->ev_r, wt->fd, EV_READ, websocket_can_read, wt);
     event_base_set(wt->base, &wt->ev_r);
     event_add(&wt->ev_r, NULL);
@@ -206,12 +381,72 @@ wait_for_possible_read(struct worker_thread *wt) {
 
 static void
 wait_for_possible_write(struct worker_thread *wt) {
+#if DEBUG_LOGS
     printf("%s (wt=%p)\n", __func__, wt);
+#endif
     event_set(&wt->ev_r, wt->fd, EV_WRITE, websocket_can_write, wt);
     event_base_set(wt->base, &wt->ev_r);
     event_add(&wt->ev_r, NULL);
 }
 
+static int
+ws_on_headers_complete(http_parser *p) {
+    struct worker_thread *wt = p->data;
+
+#if DEBUG_LOGS
+    printf("%s (wt=%p)\n", __func__, wt);
+#endif
+    // TODO
+    return 0;
+}
+
+static void
+ws_enqueue_frame_for_command(struct worker_thread *wt, char *cmd, size_t sz) {
+    unsigned char mask[4];
+    for (int i = 0; i < 4; i++) {
+        mask[i] = rand() & 0xff;
+    }
+    uint8_t len = (uint8_t)(sz); /* (1 << 7) | length. */
+    len |= (1 << 7); /* set masking bit ON */
+
+    for (int i = 0; i < sz; i++) {
+        cmd[i] = (cmd[i] ^ mask[i%4]) & 0xff;
+    }
+    /* 0x81 = 10000001b: FIN bit (only one message in the frame), text frame */
+    evbuffer_add(wt->wbuffer, "\x81", 1);
+    evbuffer_add(wt->wbuffer, &len, 1);
+    evbuffer_add(wt->wbuffer, mask, 4);
+    evbuffer_add(wt->wbuffer, cmd, sz);
+}
+
+static void
+ws_enqueue_frame(struct worker_thread *wt) {
+
+#if 0
+    char set_command[] = "[\"SET\",\"key\",\"value\"]";
+    ws_enqueue_frame_for_command(wt, set_command, sizeof(set_command) - 1);
+    char get_command[] = "[\"GET\",\"key\"]";
+    ws_enqueue_frame_for_command(wt, get_command, sizeof(get_command) - 1);
+#endif
+    char ping_command[] = "[\"PING\"]";
+    ws_enqueue_frame_for_command(wt, ping_command, sizeof(ping_command) - 1);
+
+    wait_for_possible_write(wt);
+}
+
+static int
+ws_on_message_complete(http_parser *p) {
+    struct worker_thread *wt = p->data;
+
+#if DEBUG_LOGS
+    printf("%s (wt=%p)\n", __func__, wt);
+#endif
+    // we've received the full HTTP response now, so we're ready to send frames
+    wt->state = WS_RECEIVED_HANDSHAKE;
+    ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
+    return 0;
+}
+
 void*
 worker_main(void *ptr) {
 
@@ -253,12 +488,19 @@ worker_main(void *ptr) {
     wt->byte_count = 0;
     wt->got_header = 0;
 
+    /* initialize HTTP parser, to parse the server response */
+    memset(&wt->settings, 0, sizeof(http_parser_settings));
+    wt->settings.on_headers_complete = ws_on_headers_complete;
+    wt->settings.on_message_complete = ws_on_message_complete;
+    http_parser_init(&wt->parser, HTTP_RESPONSE);
+    wt->parser.data = wt;
+
     /* build handshake buffer */
     /*
     ws_handshake_sz = sizeof(ws_handshake)
         + 2*strlen(wt->hi->host) + 500;
     ws_handshake = calloc(ws_handshake_sz, 1);
-    ws_handshake_sz = (size_t)sprintf(ws_handshake, ws_template, 
+    ws_handshake_sz = (size_t)sprintf(ws_handshake, ws_template,
             wt->hi->host, wt->hi->port,
             wt->hi->host, wt->hi->port);
     */
@@ -270,7 +512,7 @@ worker_main(void *ptr) {
     event_base_dispatch(wt->base);
     printf("event_base_dispatch returned\n");
     event_base_free(wt->base);
-    free(ws_handshake);
+    // free(ws_handshake);
     return NULL;
 }
 
@@ -391,7 +633,7 @@ main(int argc, char *argv[]) {
 
     if(total != 0) {
         printf("Read %ld messages in %0.2f sec: %0.2f msg/sec (%d MB/sec, %d KB/sec)\n",
-            (long)total, 
+            (long)total,
             (mili1-mili0)/1000.0,
             1000*total/(mili1-mili0),
             (int)(total_bytes / (1000*(mili1-mili0))),

From b0740d0c871c59195ca4ae11591e244e98a1043e Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 27 Jun 2021 18:38:51 -0700
Subject: [PATCH 03/28] Major update of websocket test

1. Switch to evbuffer for correct handling of partial writes
2. Implement WS state machine in each worker
3. Clean up debug logging
4. Add detailed network log messages to help find WS issues
5. Switch to getopt_long
---
 tests/websocket.c | 305 +++++++++++++---------------------------------
 1 file changed, 88 insertions(+), 217 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 3c53cb1..c0277d7 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -9,6 +9,7 @@
 #include <arpa/inet.h>
 #include <errno.h>
 #include <ctype.h>
+#include <getopt.h>
 
 #include <sys/types.h>
 #include <sys/socket.h>
@@ -40,6 +41,7 @@ struct worker_thread {
     int msg_received;
     int msg_sent;
     int byte_count;
+    int id;
     pthread_t thread;
     enum worker_state state;
 
@@ -55,34 +57,48 @@ struct worker_thread {
 
     http_parser parser;
     http_parser_settings settings;
+
+    int (*debug)(const char *fmt, ...);
 };
 
+int debug_noop(const char *fmt, ...) {
+    (void)fmt;
+    return 0;
+}
+
+int debug_verbose(const char *fmt, ...) {
+    int ret;
+    va_list vargs;
+    va_start(vargs, fmt);
+    ret = vfprintf(stderr, fmt, vargs);
+    va_end(vargs);
+    return ret;
+}
+
 void
-hex_dump(char *p, size_t sz) {
-#if DEBUG_LOGS
-    printf("hex dump of %p (%ld bytes)\n", p, sz);
+hex_dump(struct worker_thread *wt, char *p, size_t sz) {
+    wt->debug("hex dump of %p (%ld bytes)\n", p, sz);
     for (char *cur = p; cur < p + sz; cur += 16) {
         char letters[16] = {0};
         int limit = (cur + 16) > p + sz ? (sz % 16) : 16;
-        printf("%08lx ", cur - p); /* address */
+        wt->debug("%08lx ", cur - p); /* address */
         for (int i = 0; i < limit; i++) {
-            printf("%02x ", (unsigned int)(cur[i] & 0xff));
+            wt->debug("%02x ", (unsigned int)(cur[i] & 0xff));
             letters[i] = isprint(cur[i]) ? cur[i] : '.';
         }
         for (int i = limit; i < 16; i++) { /* pad on last line */
-            printf("   ");
+            wt->debug("   ");
         }
-        printf(" %.*s\n", limit, letters);
+        wt->debug(" %.*s\n", limit, letters);
     }
-#endif
 }
 
 void
-evbuffer_debug_dump(struct evbuffer *buffer) {
+evbuffer_debug_dump(struct worker_thread *wt, struct evbuffer *buffer) {
     size_t sz = evbuffer_get_length(buffer);
     char *data = malloc(sz);
     evbuffer_remove(buffer, data, sz);
-    hex_dump(data, sz);
+    hex_dump(wt, data, sz);
     evbuffer_prepend(buffer, data, sz);
     free(data);
 }
@@ -99,9 +115,9 @@ void
 process_message(struct worker_thread *wt, size_t sz) {
 
     // printf("process_message\n");
-    if(wt->msg_received % 10000 == 0) {
-        printf("thread %u: %8d messages left (got %9d bytes so far).\n",
-            (unsigned int)wt->thread,
+    if(wt->msg_received && wt->msg_received % 1000 == 0) {
+        printf("thread %d: %8d messages left (got %9d bytes so far).\n",
+            wt->id,
             wt->msg_target - wt->msg_received, wt->byte_count);
     }
     wt->byte_count += sz;
@@ -120,9 +136,7 @@ void
 websocket_can_write(int fd, short event, void *ptr) {
     int ret;
     struct worker_thread *wt = ptr;
-#if DEBUG_LOGS
-    printf("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
-#endif
+    wt->debug("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
 
     if(event != EV_WRITE) {
         return;
@@ -131,31 +145,23 @@ websocket_can_write(int fd, short event, void *ptr) {
     {
     case WS_INITIAL: { /* still sending initial HTTP request */
         ret = evbuffer_write(wt->wbuffer, fd);
-#if DEBUG_LOGS
-        printf("evbuffer_write returned %d\n", ret);
-        printf("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
-#endif
+        wt->debug("evbuffer_write returned %d\n", ret);
+        wt->debug("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
         if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */
             wait_for_possible_write(wt);
             return;
         }
         /* otherwise, we've sent the full request, time to read the response */
         wt->state = WS_SENT_HANDSHAKE;
-#if DEBUG_LOGS
-        printf("state=WS_SENT_HANDSHAKE\n");
-#endif
+        wt->debug("state=WS_SENT_HANDSHAKE\n");
         wait_for_possible_read(wt);
         return;
     }
     case WS_RECEIVED_HANDSHAKE: { /* ready to send a frame */
-#if DEBUG_LOGS
-        printf("About to send data for WS frame, %lu in buffer\n", evbuffer_get_length(wt->wbuffer));
-#endif
+        wt->debug("About to send data for WS frame, %lu in buffer\n", evbuffer_get_length(wt->wbuffer));
         evbuffer_write(wt->wbuffer, fd);
         size_t write_remains = evbuffer_get_length(wt->wbuffer);
-#if DEBUG_LOGS
-        printf("Sent data for WS frame, still %lu left to write\n", write_remains);
-#endif
+        wt->debug("Sent data for WS frame, still %lu left to write\n", write_remains);
         if (write_remains == 0) { /* ready to read response */
             wt->state = WS_SENT_FRAME;
             wt->msg_sent++;
@@ -168,32 +174,14 @@ websocket_can_write(int fd, short event, void *ptr) {
     default:
         break;
     }
-#if 0
-    char message[] = "\x00[\"SET\",\"key\",\"value\"]\xff\x00[\"GET\",\"key\"]\xff";
-    ret = write(fd, message, sizeof(message)-1);
-    if(ret != sizeof(message)-1) {
-        fprintf(stderr, "write on %d failed: %s\n", fd, strerror(errno));
-        close(fd);
-    }
-
-    wt->msg_sent += 2;
-    if(wt->msg_sent < wt->msg_target) {
-        event_set(&wt->ev_w, fd, EV_WRITE, websocket_can_write, wt);
-        event_base_set(wt->base, &wt->ev_w);
-        ret = event_add(&wt->ev_w, NULL);
-    }
-#endif
 }
 
 static void
 websocket_can_read(int fd, short event, void *ptr) {
-    char packet[2048], *pos;
-    int ret, success = 1;
+    int ret;
 
     struct worker_thread *wt = ptr;
-#if DEBUG_LOGS
-    printf("%s (wt=%p)\n", __func__, wt);
-#endif
+    wt->debug("%s (wt=%p)\n", __func__, wt);
 
     if(event != EV_READ) {
         return;
@@ -201,14 +189,10 @@ websocket_can_read(int fd, short event, void *ptr) {
 
     /* read message */
     ret = evbuffer_read(wt->rbuffer, fd, 65536);
-#if DEBUG_LOGS
-    printf("evbuffer_read() returned %d; wt->state=%d. wt->rbuffer:\n", ret, wt->state);
-#endif
-    evbuffer_debug_dump(wt->rbuffer);
+    wt->debug("evbuffer_read() returned %d; wt->state=%d. wt->rbuffer:\n", ret, wt->state);
+    evbuffer_debug_dump(wt, wt->rbuffer);
     if (ret == 0) {
-#if DEBUG_LOGS
-        printf("We didn't read anything from the socket...\n");
-#endif
+        wt->debug("We didn't read anything from the socket...\n");
         wait_for_possible_read(wt);
         return;
     }
@@ -218,41 +202,30 @@ websocket_can_read(int fd, short event, void *ptr) {
         case WS_SENT_HANDSHAKE: { /* waiting for handshake response */
             size_t avail_sz = evbuffer_get_length(wt->rbuffer);
             char *tmp = calloc(avail_sz, 1);
-#if DEBUG_LOGS
-            printf("avail_sz from rbuffer = %lu\n", avail_sz);
-#endif
+            wt->debug("avail_sz from rbuffer = %lu\n", avail_sz);
             evbuffer_remove(wt->rbuffer, tmp, avail_sz); /* copy into `tmp` */
-#if DEBUG_LOGS
-            printf("Giving %lu bytes to http-parser\n", avail_sz);
-#endif
+            wt->debug("Giving %lu bytes to http-parser\n", avail_sz);
             int nparsed = http_parser_execute(&wt->parser, &wt->settings, tmp, avail_sz);
-#if DEBUG_LOGS
-            printf("http-parser returned %d\n", nparsed);
-#endif
+            wt->debug("http-parser returned %d\n", nparsed);
             if (nparsed != (int)avail_sz) { // put back what we didn't read
-#if DEBUG_LOGS
-                printf("re-attach (prepend) %lu bytes\n", avail_sz - nparsed);
-#endif
+                wt->debug("re-attach (prepend) %lu byte%c\n", avail_sz - nparsed,
+                          avail_sz - nparsed > 1 ? 's' : ' ');
                 evbuffer_prepend(wt->rbuffer, tmp + nparsed, avail_sz - nparsed);
             }
             free(tmp);
             if (wt->state == WS_SENT_HANDSHAKE &&  /* haven't encountered end of response yet */
                 wt->parser.upgrade && nparsed != (int)avail_sz) {
-#if DEBUG_LOGS
-                printf("UPGRADE *and* we have some data left\n");
-#endif
+                wt->debug("UPGRADE *and* we have some data left\n");
                 continue;
             } else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
                 evbuffer_drain(wt->rbuffer, evbuffer_get_length(wt->rbuffer));
             }
+            return;
         }
-        return;
 
         case WS_SENT_FRAME: { /* waiting for frame response */
-#if DEBUG_LOGS
-            printf("We're in WS_SENT_FRAME, just read a frame response. wt->rbuffer:\n");
-#endif
-            evbuffer_debug_dump(wt->rbuffer);
+            wt->debug("We're in WS_SENT_FRAME, just read a frame response. wt->rbuffer:\n");
+            evbuffer_debug_dump(wt, wt->rbuffer);
             uint8_t flag_opcodes, payload_len;
             if (evbuffer_get_length(wt->rbuffer) < 2) { /* not enough data */
                 wait_for_possible_read(wt);
@@ -264,116 +237,27 @@ websocket_can_read(int fd, short event, void *ptr) {
             process_message(wt, payload_len);
 
             if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything, let's write again */
-#if DEBUG_LOGS
-                printf("our turn to write again\n");
-#endif
+                wt->debug("our turn to write again\n");
                 wt->state = WS_RECEIVED_HANDSHAKE;
                 ws_enqueue_frame(wt);
                 return;
             } else {
-#if DEBUG_LOGS
-                printf("there's still data to consume\n");
-#endif
+                wt->debug("there's still data to consume\n");
                 continue;
             }
-#if 0
-            struct evbuffer_ptr sof = evbuffer_search(wt->rbuffer, "\x00", 1, NULL);
-            struct evbuffer_ptr eof = evbuffer_search(wt->rbuffer, "\xff", 1, NULL);
-            if (evbuffer_get_length(wt->rbuffer) >= 1 && sof.pos != 0) {
-                printf("ERROR: length=%lu, sof at pos %ld\n", evbuffer_get_length(wt->rbuffer), sof.pos);
-            }
-            if (eof.pos == -1) { /* not there yet */
-                printf("Couldn't find the end-of-frame marker, need to read more\n");
-                wait_for_possible_read(wt);
-            } else { /* we have a frame */
-                size_t bounded_frame_sz = eof.pos + 1;
-                char *bounded_frame = calloc(bounded_frame_sz, 1);
-                evbuffer_remove(wt->rbuffer, bounded_frame, bounded_frame_sz);
-                process_message(wt, bounded_frame_sz);
-                printf("Received frame (%lu bytes total):\n", bounded_frame_sz);
-                hex_dump(bounded_frame, bounded_frame_sz);
-                free(bounded_frame);
-                if (evbuffer_get_length(wt->rbuffer) > 0) { /* we may have more frames to process */
-                    continue;
-                } else { /* our turn to send a frame */
-                    printf("Add frame to write buffer\n");
-                    ws_enqueue_frame(wt);
-                }
-            }
-#endif
+            return;
         }
-        return;
 
         default:
             return;
         }
     }
-
-#if 0
-    pos = packet;
-    if(ret > 0) {
-        char *data, *last;
-        int sz, msg_sz;
-
-        if(wt->got_header == 0) { /* first response */
-            char *frame_start = strstr(packet, "MH"); /* end of the handshake */
-            if(frame_start == NULL) {
-                return; /* not yet */
-            } else { /* start monitoring possible writes */
-                printf("start monitoring possible writes\n");
-                evbuffer_add(wt->rbuffer, frame_start + 2, ret - (frame_start + 2 - packet));
-
-                wt->got_header = 1;
-                event_set(&wt->ev_w, fd, EV_WRITE,
-                        websocket_can_write, wt);
-                event_base_set(wt->base, &wt->ev_w);
-                ret = event_add(&wt->ev_w, NULL);
-            }
-        } else {
-            /* we've had the header already, now bufffer data. */
-            evbuffer_add(wt->rbuffer, packet, ret);
-        }
-
-        while(1) {
-            data = (char*)EVBUFFER_DATA(wt->rbuffer);
-            sz = EVBUFFER_LENGTH(wt->rbuffer);
-
-            if(sz == 0) { /* no data */
-                break;
-            }
-            if(*data != 0) { /* missing frame start */
-                success = 0;
-                break;
-            }
-            last = memchr(data, 0xff, sz); /* look for frame end */
-            if(!last) {
-                /* no end of frame in sight. */
-                break;
-            }
-            msg_sz = last - data - 1;
-            process_message(ptr, msg_sz); /* record packet */
-
-            /* drain including frame delimiters (+2 bytes) */
-            evbuffer_drain(wt->rbuffer, msg_sz + 2);
-        }
-    } else {
-        printf("ret=%d\n", ret);
-        success = 0;
-    }
-    if(success == 0) {
-        shutdown(fd, SHUT_RDWR);
-        close(fd);
-        event_base_loopexit(wt->base, NULL);
-    }
-#endif
 }
 
 
 static void
 wait_for_possible_read(struct worker_thread *wt) {
-#if DEBUG_LOGS
-    printf("%s (wt=%p)\n", __func__, wt);
-#endif
+    wt->debug("%s (wt=%p)\n", __func__, wt);
     event_set(&wt->ev_r, wt->fd, EV_READ, websocket_can_read, wt);
     event_base_set(wt->base, &wt->ev_r);
     event_add(&wt->ev_r, NULL);
@@ -381,9 +265,7 @@ wait_for_possible_read(struct worker_thread *wt) {
 
 static void
 wait_for_possible_write(struct worker_thread *wt) {
-#if DEBUG_LOGS
-    printf("%s (wt=%p)\n", __func__, wt);
-#endif
+    wt->debug("%s (wt=%p)\n", __func__, wt);
     event_set(&wt->ev_r, wt->fd, EV_WRITE, websocket_can_write, wt);
     event_base_set(wt->base, &wt->ev_r);
     event_add(&wt->ev_r, NULL);
@@ -393,9 +275,7 @@ static int
 ws_on_headers_complete(http_parser *p) {
     struct worker_thread *wt = p->data;
 
-#if DEBUG_LOGS
-    printf("%s (wt=%p)\n", __func__, wt);
-#endif
+    wt->debug("%s (wt=%p)\n", __func__, wt);
     // TODO
     return 0;
 }
@@ -409,7 +289,7 @@ ws_enqueue_frame_for_command(struct worker_thread *wt, char *cmd, size_t sz) {
     uint8_t len = (uint8_t)(sz); /* (1 << 7) | length. */
     len |= (1 << 7); /* set masking bit ON */
 
-    for (int i = 0; i < sz; i++) {
+    for (size_t i = 0; i < sz; i++) {
         cmd[i] = (cmd[i] ^ mask[i%4]) & 0xff;
     }
     /* 0x81 = 10000001b: FIN bit (only one message in the frame), text frame */
@@ -421,13 +301,6 @@ ws_enqueue_frame_for_command(struct worker_thread *wt, char *cmd, size_t sz) {
 
 static void
 ws_enqueue_frame(struct worker_thread *wt) {
-
-#if 0
-    char set_command[] = "[\"SET\",\"key\",\"value\"]";
-    ws_enqueue_frame_for_command(wt, set_command, sizeof(set_command) - 1);
-    char get_command[] = "[\"GET\",\"key\"]";
-    ws_enqueue_frame_for_command(wt, get_command, sizeof(get_command) - 1);
-#endif
     char ping_command[] = "[\"PING\"]";
     ws_enqueue_frame_for_command(wt, ping_command, sizeof(ping_command) - 1);
 
@@ -438,9 +311,7 @@ static int
 ws_on_message_complete(http_parser *p) {
     struct worker_thread *wt = p->data;
 
-#if DEBUG_LOGS
-    printf("%s (wt=%p)\n", __func__, wt);
-#endif
+    wt->debug("%s (wt=%p)\n", __func__, wt);
     // we've received the full HTTP response now, so we're ready to send frames
     wt->state = WS_RECEIVED_HANDSHAKE;
     ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
@@ -464,8 +335,6 @@ worker_main(void *ptr) {
     int ret;
     int fd;
     struct sockaddr_in addr;
-    char *ws_handshake;
-    size_t ws_handshake_sz;
 
     /* connect socket */
     fd = socket(AF_INET, SOCK_STREAM, 0);
@@ -495,24 +364,15 @@ worker_main(void *ptr) {
     http_parser_init(&wt->parser, HTTP_RESPONSE);
     wt->parser.data = wt;
 
-    /* build handshake buffer */
-    /*
-    ws_handshake_sz = sizeof(ws_handshake)
-        + 2*strlen(wt->hi->host) + 500;
-    ws_handshake = calloc(ws_handshake_sz, 1);
-    ws_handshake_sz = (size_t)sprintf(ws_handshake, ws_template,
-            wt->hi->host, wt->hi->port,
-            wt->hi->host, wt->hi->port);
-    */
-    int added = evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
-                                    wt->hi->host, wt->hi->port);
+    /* add GET request to buffer */
+    evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
+                        wt->hi->host, wt->hi->port);
     wait_for_possible_write(wt); /* request callback */
 
     /* go! */
     event_base_dispatch(wt->base);
-    printf("event_base_dispatch returned\n");
+    wt->debug("event_base_dispatch returned\n");
     event_base_free(wt->base);
-    // free(ws_handshake);
     return NULL;
 }
 
@@ -524,7 +384,7 @@ usage(const char* argv0, char *host_default, short port_default,
         "Options are:\n"
         "\t-h host\t\t(default = \"%s\")\n"
         "\t-p port\t\t(default = %d)\n"
-        "\t-c threads\t(default = %d)\n"
+        "\t-t threads\t(default = %d)\n"
         "\t-n count\t(number of messages per thread, default = %d)\n"
         "\t-v\t\t(verbose)\n",
         argv0, host_default, (int)port_default,
@@ -545,15 +405,24 @@ main(int argc, char *argv[]) {
     int thread_count = thread_count_default;
     int i, opt;
     char *colon;
-    double total = 0, total_bytes = 0;
-    int verbose = 0, single = 0;
+    long total = 0, total_bytes = 0;
+    int verbose = 0;
 
     struct host_info hi = {host_default, port_default};
 
     struct worker_thread *workers;
 
     /* getopt */
-    while ((opt = getopt(argc, argv, "h:p:c:n:vs")) != -1) {
+    struct option long_options[] = {
+        {"help", no_argument, NULL, '?'},
+        {"host", required_argument, NULL, 'h'},
+        {"port", required_argument, NULL, 'p'},
+        {"threads", required_argument, NULL, 't'},
+        {"messages", required_argument, NULL, 'n'},
+        {"verbose", no_argument, NULL, 'v'},
+        {0, 0, 0, 0}
+    };
+    while ((opt = getopt_long(argc, argv, "h:p:t:n:vs", long_options, NULL)) != -1) {
         switch (opt) {
             case 'h':
                 colon = strchr(optarg, ':');
@@ -572,7 +441,7 @@ main(int argc, char *argv[]) {
                 hi.port = (short)atol(optarg);
                 break;
 
-            case 'c':
+            case 't':
                 thread_count = atoi(optarg);
                 break;
 
@@ -584,10 +453,6 @@ main(int argc, char *argv[]) {
                 verbose = 1;
                 break;
 
-            case 's':
-                single = 1;
-                thread_count = 1;
-                break;
             default: /* '?' */
                 usage(argv[0], host_default, port_default,
                         thread_count_default,
@@ -600,20 +465,25 @@ main(int argc, char *argv[]) {
     workers = calloc(sizeof(struct worker_thread), thread_count);
 
     clock_gettime(CLOCK_MONOTONIC, &t0);
-    if (single) {
+    if (thread_count == 1) {
         printf("Single-threaded mode\n");
+        workers[0].id = 0;
         workers[0].msg_target = msg_target;
         workers[0].hi = &hi;
         workers[0].verbose = verbose;
         workers[0].state = WS_INITIAL;
+        workers[0].debug = verbose ? debug_verbose : debug_noop;
         worker_main(&workers[0]);
+        total = workers[0].msg_received;
+        total_bytes = workers[0].byte_count;
     } else {
         for (i = 0; i < thread_count; ++i) {
+            workers[i].id = i;
             workers[i].msg_target = msg_target;
             workers[i].hi = &hi;
             workers[i].verbose = verbose;
             workers[i].state = WS_INITIAL;
-
+            workers[i].debug = verbose ? debug_verbose : debug_noop;
             pthread_create(&workers[i].thread, NULL,
                            worker_main, &workers[i]);
         }
@@ -632,12 +502,13 @@ main(int argc, char *argv[]) {
     float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
 
     if(total != 0) {
-        printf("Read %ld messages in %0.2f sec: %0.2f msg/sec (%d MB/sec, %d KB/sec)\n",
-            (long)total,
+        double kb_per_sec = ((double)total_bytes / (double)(mili1-mili0)) / 1.024;
+        printf("Read %ld messages (%ld bytes) in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
+            total,
+            total_bytes,
             (mili1-mili0)/1000.0,
-            1000*total/(mili1-mili0),
-            (int)(total_bytes / (1000*(mili1-mili0))),
-            (int)(total_bytes / (mili1-mili0)));
+            1000*((double)total)/(mili1-mili0),
+            kb_per_sec);
         return EXIT_SUCCESS;
     } else {
         printf("No message was read.\n");

From 5a53c31a278dac06340940964d58580d8c6061d3 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 12:05:14 -0700
Subject: [PATCH 04/28] Logging improvements: add tracing, level check

* Add WEBDIS_TRACE log level for internal operations
* Warn when verbosity config is invalid
* Add slog_enabled to bypass buffer allocations if the level is filtered
---
 src/conf.c |  8 +++++---
 src/slog.c | 12 ++++++++++--
 src/slog.h |  6 +++++-
 3 files changed, 20 insertions(+), 6 deletions(-)

diff --git a/src/conf.c b/src/conf.c
index 92a68fc..f886b57 100644
--- a/src/conf.c
+++ b/src/conf.c
@@ -159,9 +159,11 @@ conf_read(const char *filename) {
 			}
 		} else if(strcmp(json_object_iter_key(kv),"verbosity") == 0 && json_typeof(jtmp) == JSON_INTEGER){
 			int tmp = json_integer_value(jtmp);
-			if(tmp < 0) conf->verbosity = WEBDIS_ERROR;
-			else if(tmp > (int)WEBDIS_DEBUG) conf->verbosity = WEBDIS_DEBUG;
-			else conf->verbosity = (log_level)tmp;
+			if(tmp < 0 || tmp > (int)WEBDIS_TRACE) {
+				fprintf(stderr, "Invalid log verbosity: %d. Acceptable range: [%d .. %d]\n",
+					tmp, WEBDIS_ERROR, WEBDIS_TRACE);
+			}
+			conf->verbosity = (tmp < 0 ? WEBDIS_ERROR : (tmp > WEBDIS_TRACE ? WEBDIS_TRACE : (log_level)tmp));
 		} else if(strcmp(json_object_iter_key(kv), "daemonize") == 0 && json_typeof(jtmp) == JSON_TRUE) {
 			conf->daemonize = 1;
 		} else if(strcmp(json_object_iter_key(kv), "daemonize") == 0 && json_typeof(jtmp) == JSON_STRING) {
diff --git a/src/slog.c b/src/slog.c
index 4c30438..3a48680 100644
--- a/src/slog.c
+++ b/src/slog.c
@@ -76,6 +76,14 @@ slog_fsync_init(struct server *s) {
 	}
 }
 
+/**
+ * Returns whether this log level is enabled.
+ */
+int
+slog_enabled(struct server *s, log_level level) {
+	return level <= s->cfg->verbosity ? 1 : 0;
+}
+
 /**
  * Write log message to disk, or stderr.
  */
@@ -83,6 +91,8 @@ void
 slog(struct server *s, log_level level,
 		const char *body, size_t sz) {
 
+	if(level > s->cfg->verbosity) return; /* too verbose */
+
 	const char *c = "EWNID";
 	time_t now;
 	struct tm now_tm, *lt_ret;
@@ -91,8 +101,6 @@ slog(struct server *s, log_level level,
 	char line[256]; /* bounds are checked. */
 	int line_sz, ret;
 
-	if(level > s->cfg->verbosity) return; /* too verbose */
-
 	if(!s->log.fd) return;
 
 	/* limit message size */
diff --git a/src/slog.h b/src/slog.h
index f521d9a..9400702 100644
--- a/src/slog.h
+++ b/src/slog.h
@@ -6,7 +6,8 @@ typedef enum {
 	WEBDIS_WARNING,
 	WEBDIS_NOTICE,
 	WEBDIS_INFO,
-	WEBDIS_DEBUG
+	WEBDIS_DEBUG,
+	WEBDIS_TRACE
 } log_level;
 
 typedef enum {
@@ -26,6 +27,9 @@ slog_init(struct server *s);
 void
 slog_fsync_init(struct server *s);
 
+int
+slog_enabled(struct server *s, log_level level);
+
 void slog(struct server *s, log_level level,
 		const char *body, size_t sz);
 

From 873f1b59029fa7794e9b40e30e2520264a308f81 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 12:09:09 -0700
Subject: [PATCH 05/28] Add trace logs to websocket code, event loop functions

Mostly adding trace logs to websocket.c, but also some in http.c and
worker.c for events relating to event loop and client requests and
responses. This is useful for debugging websocket issues.
---
 src/http.c      | 23 ++++++++++--
 src/websocket.c | 98 ++++++++++++++++++++++++++++++++++++++-----------
 src/worker.c    |  6 +--
 3 files changed, 99 insertions(+), 28 deletions(-)

diff --git a/src/http.c b/src/http.c
index 6b7acd2..da396a8 100644
--- a/src/http.c
+++ b/src/http.c
@@ -2,6 +2,7 @@
 #include "server.h"
 #include "worker.h"
 #include "client.h"
+#include "slog.h"
 
 #include <string.h>
 #include <stdlib.h>
@@ -98,7 +99,12 @@ http_response_cleanup(struct http_response *r, int fd, int success) {
 	free(r->out);
 	if(!r->keep_alive || !success) {
 		/* Close fd is client doesn't support Keep-Alive. */
-		fprintf(stderr, "http_response_cleanup: keep_alive=%d, success=%d -> closing\n", r->keep_alive, success);
+		if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) {
+			char format[] = "http_response_cleanup: keep_alive=%d, success=%d -> closing";
+			char cleanup_msg[sizeof(format)];
+			snprintf(cleanup_msg, sizeof(cleanup_msg), format, r->keep_alive ? 1 : 0, success ? 1: 0);
+			slog(r->w->s, WEBDIS_TRACE, cleanup_msg, 0);
+		}
 		close(fd);
 	}
 
@@ -125,8 +131,19 @@ http_can_write(int fd, short event, void *p) {
 	if(ret > 0)
 		r->sent += ret;
 
-	fprintf(stderr, "http_can_write: ret=%d, r->out_sz=%lu, r->sent=%d\n",
-		ret, r->out_sz, r->sent);
+	if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) { /* trace logs */
+		char format[] = "http_can_write: wrote %d, remaining=%lu, total sent=%d";
+		size_t contents_sz = snprintf(NULL, 0, format, ret, r->out_sz - r->sent, r->sent);
+		char *contents_msg = calloc(contents_sz + 1, 1);
+		if (contents_msg) {
+			snprintf(contents_msg, contents_sz + 1, format, ret, r->out_sz - r->sent, r->sent);
+			slog(r->w->s, WEBDIS_TRACE, contents_msg, contents_sz);
+			free(contents_msg);
+		} else {
+			slog(r->w->s, WEBDIS_ERROR, "Failed allocation in http_can_write", 0);
+		}
+	}
+
 	if(ret <= 0 || r->out_sz - r->sent == 0) { /* error or done */
 		http_response_cleanup(r, fd, (int)r->out_sz == r->sent ? 1 : 0);
 	} else { /* reschedule write */
diff --git a/src/websocket.c b/src/websocket.c
index 687fbfe..c8482f6 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -6,6 +6,7 @@
 #include "worker.h"
 #include "pool.h"
 #include "http.h"
+#include "slog.h"
 
 /* message parsers */
 #include "formats/json.h"
@@ -219,13 +220,13 @@ ws_execute(struct http_client *c, const char *frame, size_t frame_len) {
 }
 
 static struct ws_msg *
-ws_msg_new() {
-	fprintf(stderr, "------------ NEW -----------\n");
+ws_msg_new(struct server *s) {
+	slog(s, WEBDIS_TRACE, "ws_msg_new", 0);
 	return calloc(1, sizeof(struct ws_msg));
 }
 
 static void
-ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) {
+ws_msg_add(struct server *s, struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) {
 
 	/* add data to frame */
 	size_t i;
@@ -236,22 +237,35 @@ ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mas
 	for(i = 0; i < psz && mask; ++i) {
 		m->payload[m->payload_sz + i] = (unsigned char)p[i] ^ mask[i%4];
 	}
-	fprintf(stderr, "CONTENTS=[%.*s] (%lu)\n", (int)psz, m->payload, psz);
+	if (slog_enabled(s, WEBDIS_TRACE)) {
+		char format[] = "ws_msg_add: %lu bytes, mask_enabled=%c";
+		char mask_enabled = mask ? 'Y' : 'N';
+
+		size_t contents_sz = snprintf(NULL, 0, format, psz, mask_enabled);
+		char *contents_msg = calloc(contents_sz + 1, 1);
+		if (contents_msg) {
+			snprintf(contents_msg, contents_sz + 1, format, psz, mask_enabled);
+			slog(s, WEBDIS_TRACE, contents_msg, contents_sz);
+			free(contents_msg);
+		} else {
+			slog(s, WEBDIS_ERROR, "Failed allocation in ws_msg_add", 0);
+		}
+	}
 
 	/* save new size */
 	m->payload_sz += psz;
 }
 
 static void
-ws_msg_free(struct ws_msg **m) {
-	fprintf(stderr, "------------ /FREE -----------\n");
+ws_msg_free(struct server *s, struct ws_msg **m) {
+	slog(s, WEBDIS_TRACE, "ws_msg_free", 0);
 	free((*m)->payload);
 	free(*m);
 	*m = NULL;
 }
 
 static enum ws_state
-ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
+ws_parse_data(struct server *s, const char *frame, size_t sz, struct ws_msg **msg) {
 
 	int has_mask;
 	uint64_t len;
@@ -264,15 +278,30 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
 	}
 
 	has_mask = frame[1] & 0x80 ? 1:0;
-	fprintf(stderr, "has_mask=%d\n", has_mask);
+	if (slog_enabled(s, WEBDIS_TRACE)) {
+		char log_mask[]= "ws_parse_data: has_mask=?";
+		log_mask[sizeof(log_mask)-2] = has_mask ? 'Y' : 'N'; /* -1 for \0 and -1 again for last char */
+		slog(s, WEBDIS_TRACE, log_mask, sizeof(log_mask)-1);
+	}
 
 	/* get payload length */
 	len = frame[1] & 0x7f;	/* remove leftmost bit */
-	fprintf(stderr, "len=%llu\n", len);
+
+	if (slog_enabled(s, WEBDIS_TRACE)) { /* log length */
+		char format[] = "ws_parse_data: payload length = %llu bytes";
+		size_t contents_sz = snprintf(NULL, 0, format, len);
+		char *contents_msg = calloc(contents_sz + 1, 1);
+		if (contents_msg) {
+			snprintf(contents_msg, contents_sz + 1, format, len);
+			slog(s, WEBDIS_TRACE, contents_msg, contents_sz);
+			free(contents_msg);
+		} else {
+			slog(s, WEBDIS_ERROR, "Failed allocation in ws_parse_data", 0);
+		}
+	}
 	if(len <= 125) { /* data starts right after the mask */
 		p = frame + 2 + (has_mask ? 4 : 0);
 		if(has_mask) memcpy(&mask, frame + 2, sizeof(mask));
-		if (has_mask) fprintf(stderr, "mask= %02x %02x %02x %02x\n", mask[0], mask[1], mask[2], mask[3]);
 	} else if(len == 126) {
 		uint16_t sz16;
 		memcpy(&sz16, frame + 2, sizeof(uint16_t));
@@ -293,15 +322,15 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
 	}
 
 	if(!*msg)
-		*msg = ws_msg_new();
-	ws_msg_add(*msg, p, len, has_mask ? mask : NULL);
+		*msg = ws_msg_new(s);
+	ws_msg_add(s, *msg, p, len, has_mask ? mask : NULL);
 	(*msg)->total_sz += len + (p - frame);
 
 	if(frame[0] & 0x80) { /* FIN bit set */
-		fprintf(stderr, "FIN bit: SET\n");
+		slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit set", 0);
 		return WS_MSG_COMPLETE;
 	} else {
-		fprintf(stderr, "FIN bit: NOT SET\n");
+		slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit not set", 0);
 		return WS_READING;	/* need more data */
 	}
 }
@@ -315,32 +344,43 @@ ws_add_data(struct http_client *c) {
 
 	enum ws_state state;
 
-	state = ws_parse_data(c->buffer, c->sz, &c->frame);
+	state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame);
 
 	while(state == WS_MSG_COMPLETE) {
 		int ret = ws_execute(c, c->frame->payload, c->frame->payload_sz);
-		fprintf(stderr, "ws_execute returned %d\n", ret);
+		if (slog_enabled(c->s, WEBDIS_TRACE)) {
+			char format[] = "ws_add_data: ws_execute(payload_sz=%lu) returned %d";
+
+			size_t contents_sz = snprintf(NULL, 0, format, c->frame->payload_sz, ret);
+			char *contents_msg = calloc(contents_sz + 1, 1);
+			if (contents_msg) {
+				snprintf(contents_msg, contents_sz + 1, format, c->frame->payload_sz, ret);
+				slog(c->s, WEBDIS_TRACE, contents_msg, contents_sz);
+				free(contents_msg);
+			} else {
+				slog(c->s, WEBDIS_ERROR, "Failed allocation in ws_add_data", 0);
+			}
+		}
 
 		/* remove frame from client buffer */
 		http_client_remove_data(c, c->frame->total_sz);
 
 		/* free frame and set back to NULL */
-		ws_msg_free(&c->frame);
+		ws_msg_free(c->s, &c->frame);
 
 		if(ret != 0) {
 			/* can't process frame. */
+			slog(c->s, WEBDIS_WARNING, "ws_add_data: ws_execute failed", 0);
 			return WS_ERROR;
 		}
-		fprintf(stderr, "Calling ws_parse_data again...\n");
-		state = ws_parse_data(c->buffer, c->sz, &c->frame);
-		fprintf(stderr, "ws_parse_data returned %d\n", (int)state);
+		slog(c->s, WEBDIS_TRACE, "ws_add_data: calling ws_parse_data again", 0);
+		state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame);
 	}
 	return state;
 }
 
 int
 ws_reply(struct cmd *cmd, const char *p, size_t sz) {
-	fprintf(stderr, "ws_reply: '%.*s' (%lu bytes)\n", (int)sz, p, sz);
 	char *frame = malloc(sz + 8); /* create frame by prepending header */
 	size_t frame_sz = 0;
 	struct http_response *r;
@@ -375,7 +415,7 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) {
 
 	/* send WS frame */
 	r = http_response_init(cmd->w, 0, NULL);
-	if (1 || cmd_is_subscribe(cmd)) {
+	if (cmd_is_subscribe(cmd)) {
 		r->keep_alive = 1;
 	}
 
@@ -385,6 +425,20 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) {
 	r->out = frame;
 	r->out_sz = frame_sz;
 	r->sent = 0;
+
+	if (slog_enabled(cmd->w->s, WEBDIS_TRACE)) {
+		char format[] = "ws_reply: response is %lu bytes, frame is %lu";
+		size_t contents_sz = snprintf(NULL, 0, format, sz, frame_sz);
+		char *contents_msg = calloc(contents_sz + 1, 1);
+		if (contents_msg) {
+			snprintf(contents_msg, contents_sz + 1, format, sz, frame_sz);
+			slog(cmd->w->s, WEBDIS_TRACE, contents_msg, contents_sz);
+			free(contents_msg);
+		} else {
+			slog(cmd->w->s, WEBDIS_ERROR, "Failed allocation in ws_reply", 0);
+		}
+	}
+
 	http_schedule_write(cmd->fd, r);
 
 	return 0;
diff --git a/src/worker.c b/src/worker.c
index 1d5b838..747c5ff 100644
--- a/src/worker.c
+++ b/src/worker.c
@@ -35,13 +35,13 @@ worker_new(struct server *s) {
 
 void
 worker_can_read(int fd, short event, void *p) {
-	fprintf(stderr, "worker_can_read\n");
 	struct http_client *c = p;
 	int ret, nparsed;
 
 	(void)fd;
 	(void)event;
 
+	slog(c->w->s, WEBDIS_TRACE, "worker_can_read", 0);
 	ret = http_client_read(c);
 	if(ret <= 0) {
 		if((client_error_t)ret == CLIENT_DISCONNECTED) {
@@ -87,11 +87,11 @@ worker_can_read(int fd, short event, void *p) {
 	}
 
 	if(c->broken) { /* terminate client */
-		fprintf(stderr, "c->broken: http_client_free()\n");
+		slog(c->s, WEBDIS_TRACE, "worker_can_read: c->broken, calling http_client_free", 0);
 		http_client_free(c);
 	} else {
 		/* start monitoring input again */
-		fprintf(stderr, "worker_monitor_input()\n");
+		slog(c->s, WEBDIS_TRACE, "worker_can_read: calling worker_monitor_input again", 0);
 		worker_monitor_input(c);
 	}
 }

From 71a30e9d3aa9175e6000f264d1963172dbea8d4c Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 12:13:14 -0700
Subject: [PATCH 06/28] Lower default verbosity level for webdis.json

In prod config, level is even lower and does not need to change
---
 webdis.json | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/webdis.json b/webdis.json
index 534ee8c..09d782c 100644
--- a/webdis.json
+++ b/webdis.json
@@ -26,6 +26,6 @@
 		}
 	],
 
-	"verbosity": 6,
+	"verbosity": 4,
 	"logfile": "webdis.log"
 }

From b46bb8504be413a5dfae24b325c3b134aeaf02ea Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 13:16:15 -0700
Subject: [PATCH 07/28] Mark websocket http responses as keep_alive

The keep_alive flag is needed on http_response for websocket
connections. Without it, the server closes the connection as soon as a
reply to the first frame is sent.
---
 src/websocket.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/src/websocket.c b/src/websocket.c
index c8482f6..8aae00e 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -415,12 +415,14 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) {
 
 	/* send WS frame */
 	r = http_response_init(cmd->w, 0, NULL);
-	if (cmd_is_subscribe(cmd)) {
-		r->keep_alive = 1;
+	if (r == NULL) {
+		free(frame);
+		slog(cmd->w->s, WEBDIS_ERROR, "Failed response allocation in ws_reply", 0);
+		return -1;
 	}
 
-	if (r == NULL)
-		return -1;
+	/* mark as keep alive, otherwise we'll close the connection after the first reply */
+	r->keep_alive = 1;
 
 	r->out = frame;
 	r->out_sz = frame_sz;

From a15fb4e28e8b9a47c59b03d41fd08bfce9b3699d Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 14:47:15 -0700
Subject: [PATCH 08/28] Modernize websocket.html web page

* Use pure.css for a basic grid
* Detect disconnections, update UI accordingly
* Make GET/SET commands configurable and interactive
* Add button to clear logs
* Test with current branch
---
 tests/websocket.html | 295 ++++++++++++++++++++++++++-----------------
 1 file changed, 180 insertions(+), 115 deletions(-)

diff --git a/tests/websocket.html b/tests/websocket.html
index a30f936..049ff00 100644
--- a/tests/websocket.html
+++ b/tests/websocket.html
@@ -3,150 +3,215 @@
 	<head>
 		<title>WebSocket example</title>
 		<meta charset="utf-8" />
+		<meta name="viewport" content="width=device-width, initial-scale=1">
+		<link rel="stylesheet" href="https://unpkg.com/purecss@2.0.6/build/pure-min.css" integrity="sha384-Uu6IeWbM+gzNVXJcM9XV3SohHtmWE+3VGi496jvgX1jyvDTXfdK+rfZc8C1Aehk5" crossorigin="anonymous">
 		<style type="text/css">
-
-			body {
-				width: 800px;
-				margin: auto;
-			}
-
-			header {
-				font-size: 36pt;
-				width: 100%;
+			h1, h3 {
 				text-align: center;
-				margin-bottom: 1em;
-				color: #541F14;
-			}
-
-			section.proto {
-				float: left;
-				/*background-color: #f8f8f8;*/
-			}
-
-			section#json {
-				width: 380px;
-				margin-right: 20px;
-			}
-
-			section#raw {
-				width: 380px;
-				padding-left: 16px;
-				border-left: 4px solid #626266;
 			}
 
-			div.desc {
-				margin: 0px;
-			}
 			pre.sent, pre.received {
 				margin-top: 0px;
 				border-radius: 4px;
 				padding: 5px;
 			}
+
 			pre.sent {
-				border: 1px solid #938172;
+				border: 1px solid #4b63cc;
 				background-color: white;
 			}
+
 			pre.received {
-				border: 1px solid #CC9E61;
+				border: 1px solid #4db96d;
 				text-align: right;
 			}
 
+			.ws-state {
+				font-weight: bold;
+				line-height: 18px;
+				vertical-align: middle;
+			}
+
+			div.log {
+				font-size: 13pt;
+			}
 		</style>
 	</head>
 
 	<body>
-		<header>Webdis with HTML5 WebSockets</header>
-
-		<section class="proto" id="json">
-			<h3>JSON</h3>
-			<div class="log" id="json-log">
-				Connecting...
+		<div class="pure-g">
+		<h1 class="pure-u-1">Webdis with HTML5 WebSockets</h1>
+		</div>
+
+		<div class="pure-g">
+			<div class="pure-u-1-8"></div>
+			<div class="pure-u-1-3">
+				<h3>JSON</h3>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-2-3"><label class="ws-state pure-u-23-24" id="json-state">State: Disconnected</label></div>
+							<div class="pure-u-1-3"><button type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-connect">Connect</button></div>
+						</div>
+					</fieldset>
+				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="json-set-key" value="hello" /></div>
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="value" id="json-set-value" value="world" /></div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-set">SET</button></div>
+						</div>
+					</fieldset>
+				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-1-3">&nbsp;</div>
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="json-get-key" value="hello" /></div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-get">GET</button></div>
+						</div>
+					</fieldset>
+				</form>
+
+				<div class="pure-g">
+					<div class="pure-u-2-3">&nbsp;</div>
+					<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-clear">Clear logs</button></div>
+					<div class="log pure-u-1-1" id="json-log">
+					</div>
+				</div>
 			</div>
-		</section>
-		<section class="proto" id="raw">
-			<h3>Raw</h3>
-			<div class="log" id="raw-log">
-				Connecting...
+
+			<!-- spacer -->
+			<div class="pure-u-1-12"></div>
+
+			<div class="pure-u-1-3">
+				<h3>Raw</h3>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-2-3"><label class="ws-state pure-u-23-24" id="raw-state">State: Disconnected</label></div>
+							<div class="pure-u-1-3"><button type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-connect">Connect</button></div>
+						</div>
+					</fieldset>
+				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="raw-set-key" value="hello" /></div>
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="value" id="raw-set-value" value="world" /></div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-set">SET</button></div>
+						</div>
+					</fieldset>
+				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-1-3">&nbsp;</div>
+							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="raw-get-key" value="hello" /></div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-get">GET</button></div>
+						</div>
+					</fieldset>
+				</form>
+
+				<div class="pure-g">
+					<div class="pure-u-2-3">&nbsp;</div>
+					<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-clear">Clear logs</button></div>
+					<div class="log pure-u-1-1" id="raw-log">
+					</div>
+				</div>
 			</div>
-		</section>
 
+			<div class="pure-u-1-8"></div>
+		</div>
 
-		<script type="text/javascript">
+<script type="text/javascript">
 
 $ = function(id) {return document.getElementById(id);};
-var host = "127.0.0.1";
-var port = 7379;
-
-function log(id, dir, msg) {
-
-	var desc = document.createElement("div");
-	desc.setAttribute("class", "desc");
-	desc.innerHTML = dir;
-	$(id).appendChild(desc);
-
-	var e = document.createElement("pre");
-	e.setAttribute("class", dir);
-	e.innerHTML = msg;
-	$(id).appendChild(e);
-}
-
-function testJSON() {
-
-	if(typeof(WebSocket) == 'function')
-		f = WebSocket;
-	if(typeof(MozWebSocket) == 'function')
-		f = MozWebSocket;
-
-	var jsonSocket = new f("ws://"+host+":"+port+"/.json");
-	var self = this;
-
-	send = function(j) {
-		var json = JSON.stringify(j);
-		jsonSocket.send(json);
-		log("json-log", "sent", json);
-	};
-
-	jsonSocket.onopen = function() {
-		$("json-log").innerHTML = "";
-		self.send(["SET", "hello", "world"]);
-		self.send(["GET", "hello"]);
-	};
-
-	jsonSocket.onmessage = function(messageEvent) {
-		log("json-log", "received", messageEvent.data);
-	};
+const host = "127.0.0.1";
+const port = 7379;
+
+class Client {
+	constructor(type, getSerializer, setSerializer) {
+		this.type = type;
+		this.getSerializer = getSerializer;
+		this.setSerializer = setSerializer;
+		this.ws = null;
+
+		$(`${this.type}-btn-connect`).addEventListener('click', event => {
+			event.preventDefault();
+			console.log('Connecting...');
+			this.ws = new WebSocket(`ws://${ host }:${ port }/.${ this.type }`);
+			this.ws.onopen = event => {
+				console.log('Connected');
+				this.setConnectedState(true);
+			};
+
+			// log received messages
+			this.ws.onmessage = messageEvent => {
+				this.log("received", messageEvent.data);
+			};
+
+			this.ws.onclose = event => {
+				$(`${this.type}-btn-connect`).disabled = false;
+				this.setConnectedState(false);
+			};
+		});
+
+		$(`${this.type}-btn-set`).addEventListener('click', event => {
+			event.preventDefault();
+			const serialized = this.setSerializer($(`${this.type}-set-key`).value, $(`${this.type}-set-value`).value);
+			this.log("sent", serialized);
+			this.ws.send(serialized);
+		});
+
+		$(`${this.type}-btn-get`).addEventListener('click', event => {
+			event.preventDefault();
+			const serialized = this.getSerializer($(`${this.type}-set-key`).value);
+			this.log("sent", serialized);
+			this.ws.send(serialized);
+		});
+
+		$(`${this.type}-btn-clear`).addEventListener('click', event => {
+			event.preventDefault();
+			$(`${this.type}-log`).innerText = "";
+		});
+	}
+
+	setConnectedState(connected) {
+		$(`${this.type}-btn-connect`).disabled = connected;
+		$(`${this.type}-set-key`).disabled = !connected;
+		$(`${this.type}-set-value`).disabled = !connected;
+		$(`${this.type}-btn-set`).disabled = !connected;
+		$(`${this.type}-get-key`).disabled = !connected;
+		$(`${this.type}-btn-get`).disabled = !connected;
+		$(`${this.type}-btn-clear`).disabled = !connected;
+		$(`${this.type}-state`).innerText = `State: ${connected ? 'Connected' : 'Disconnected'}`;
+	}
+
+	log(dir, msg) {
+		const id = `${this.type}-log`;
+
+		const description = document.createElement("div");
+		description.innerHTML = dir;
+		$(id).appendChild(description);
+
+		const contents = document.createElement("pre");
+		contents.setAttribute("class", dir);
+		contents.innerHTML = msg;
+		$(id).appendChild(contents);
+	}
 }
 
-function testRAW() {
-
-	if(typeof(WebSocket) == 'function')
-		f = WebSocket;
-	if(typeof(MozWebSocket) == 'function')
-		f = MozWebSocket;
-
-	var rawSocket = new f("ws://"+host+":"+port+"/.raw");
-	var self = this;
-
-	sendRaw = function(raw) {
-		rawSocket.send(raw);
-		log("raw-log", "sent", raw);
-	};
-
-	rawSocket.onopen = function() {
-		$("raw-log").innerHTML = "";
-		self.sendRaw("*3\r\n$3\r\nSET\r\n$5\r\nhello\r\n$5\r\nworld\r\n");
-		self.sendRaw("*2\r\n$3\r\nGET\r\n$5\r\nhello\r\n");
-	};
-
-	rawSocket.onmessage = function(messageEvent) {
-		log("raw-log", "received", messageEvent.data);
-	};
-}
+addEventListener("DOMContentLoaded", () => {
+	const jsonClient = new Client('json',
+		(key) => JSON.stringify(['GET', key]),
+		(key, value) => JSON.stringify(['SET', key, value]));
 
-addEventListener("DOMContentLoaded", function(){
-	testJSON();
-	testRAW();
-}, null);
+	const rawClient = new Client('raw',
+		(key) => `*2\r\n$3\r\nGET\r\n$${key.length}\r\n${key}\r\n`,
+		(key, value) =>  `*3\r\n$3\r\nSET\r\n$${key.length}\r\n${key}\r\n$${value.length}\r\n${value}\r\n`);
+});
 
 		</script>
 	</body>

From 2576a1606d112ff3ace67d3be6c24db7350dc242 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 15:12:07 -0700
Subject: [PATCH 09/28] Websocket test: clean up usage(), exit code

* Better usage() help page
* Do not submit another frame once we've sent all we needed
---
 tests/websocket.c | 33 ++++++++++++++++++---------------
 1 file changed, 18 insertions(+), 15 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index c0277d7..16a1987 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -125,6 +125,8 @@ process_message(struct worker_thread *wt, size_t sz) {
     /* decrement read count, and stop receiving when we reach zero. */
     wt->msg_received++;
     if(wt->msg_received == wt->msg_target) {
+        wt->debug("%s: thread %d has received all %d messages it expected\n",
+            __func__, wt->id, wt->msg_received);
         event_base_loopexit(wt->base, NULL);
     }
 }
@@ -193,7 +195,6 @@ websocket_can_read(int fd, short event, void *ptr) {
     evbuffer_debug_dump(wt, wt->rbuffer);
     if (ret == 0) {
         wt->debug("We didn't read anything from the socket...\n");
-        wait_for_possible_read(wt);
         return;
     }
 
@@ -236,10 +237,12 @@ websocket_can_read(int fd, short event, void *ptr) {
             evbuffer_drain(wt->rbuffer, (size_t)payload_len); /* remove payload itself */
             process_message(wt, payload_len);
 
-            if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything, let's write again */
-                wt->debug("our turn to write again\n");
-                wt->state = WS_RECEIVED_HANDSHAKE;
-                ws_enqueue_frame(wt);
+            if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything */
+                if (wt->msg_received < wt->msg_target) { /* let's write again */
+                    wt->debug("our turn to write again\n");
+                    wt->state = WS_RECEIVED_HANDSHAKE;
+                    ws_enqueue_frame(wt);
+                } /* otherwise, we're done */
                 return;
             } else {
                 wt->debug("there's still data to consume\n");
@@ -382,11 +385,11 @@ usage(const char* argv0, char *host_default, short port_default,
 
     printf("Usage: %s [options]\n"
         "Options are:\n"
-        "\t-h host\t\t(default = \"%s\")\n"
-        "\t-p port\t\t(default = %d)\n"
-        "\t-t threads\t(default = %d)\n"
-        "\t-n count\t(number of messages per thread, default = %d)\n"
-        "\t-v\t\t(verbose)\n",
+        "\t[--host|-h] HOST\t(default = \"%s\")\n"
+        "\t[--port|-p] PORT\t(default = %d)\n"
+        "\t[--clients|-c] THREADS\t(default = %d)\n"
+        "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
+        "\t[--verbose|-v]\t\t(extremely verbose output)\n",
         argv0, host_default, (int)port_default,
         thread_count_default, messages_default);
 }
@@ -417,12 +420,12 @@ main(int argc, char *argv[]) {
         {"help", no_argument, NULL, '?'},
         {"host", required_argument, NULL, 'h'},
         {"port", required_argument, NULL, 'p'},
-        {"threads", required_argument, NULL, 't'},
+        {"clients", required_argument, NULL, 'c'},
         {"messages", required_argument, NULL, 'n'},
         {"verbose", no_argument, NULL, 'v'},
         {0, 0, 0, 0}
     };
-    while ((opt = getopt_long(argc, argv, "h:p:t:n:vs", long_options, NULL)) != -1) {
+    while ((opt = getopt_long(argc, argv, "h:p:c:n:vs", long_options, NULL)) != -1) {
         switch (opt) {
             case 'h':
                 colon = strchr(optarg, ':');
@@ -441,7 +444,7 @@ main(int argc, char *argv[]) {
                 hi.port = (short)atol(optarg);
                 break;
 
-            case 't':
+            case 'c':
                 thread_count = atoi(optarg);
                 break;
 
@@ -457,7 +460,7 @@ main(int argc, char *argv[]) {
                 usage(argv[0], host_default, port_default,
                         thread_count_default,
                         messages_default);
-                exit(EXIT_FAILURE);
+                exit(EXIT_SUCCESS);
         }
     }
 
@@ -509,7 +512,7 @@ main(int argc, char *argv[]) {
             (mili1-mili0)/1000.0,
             1000*((double)total)/(mili1-mili0),
             kb_per_sec);
-        return EXIT_SUCCESS;
+        return (total == thread_count * msg_target ? EXIT_SUCCESS : EXIT_FAILURE);
     } else {
         printf("No message was read.\n");
         return EXIT_FAILURE;

From 665fc19126fc6bda97c271ffeaefa6a7707c246e Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 15:32:33 -0700
Subject: [PATCH 10/28] Add max execution time to tests/websocket.c

* Add --max-time in seconds
* Break client loop when elapsed
---
 tests/websocket.c | 71 +++++++++++++++++++++++++++++++----------------
 1 file changed, 47 insertions(+), 24 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 16a1987..0151c6f 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -44,6 +44,7 @@ struct worker_thread {
     int id;
     pthread_t thread;
     enum worker_state state;
+    int timeout_seconds;
 
     struct evbuffer *rbuffer;
     int got_header;
@@ -321,6 +322,16 @@ ws_on_message_complete(http_parser *p) {
     return 0;
 }
 
+static void
+ws_on_timeout(evutil_socket_t fd, short event, void *arg) {
+    struct worker_thread *wt = arg;
+    (void) fd;
+    (void) event;
+
+    fprintf(stderr, "Time has run out! (thread %d)\n", wt->id);
+    event_base_loopbreak(wt->base); /* break out of event loop */
+}
+
 void*
 worker_main(void *ptr) {
 
@@ -338,6 +349,8 @@ worker_main(void *ptr) {
     int ret;
     int fd;
     struct sockaddr_in addr;
+    struct timeval timeout_tv;
+    struct event *timeout_ev;
 
     /* connect socket */
     fd = socket(AF_INET, SOCK_STREAM, 0);
@@ -360,6 +373,14 @@ worker_main(void *ptr) {
     wt->byte_count = 0;
     wt->got_header = 0;
 
+    /* add timeout, if set */
+    if (wt->timeout_seconds > 0) {
+        timeout_tv.tv_sec = wt->timeout_seconds;
+        timeout_tv.tv_usec = 0;
+        timeout_ev = event_new(wt->base, -1, EV_TIMEOUT, ws_on_timeout, wt);
+        event_add(timeout_ev, &timeout_tv);
+    }
+
     /* initialize HTTP parser, to parse the server response */
     memset(&wt->settings, 0, sizeof(http_parser_settings));
     wt->settings.on_headers_complete = ws_on_headers_complete;
@@ -389,6 +410,7 @@ usage(const char* argv0, char *host_default, short port_default,
         "\t[--port|-p] PORT\t(default = %d)\n"
         "\t[--clients|-c] THREADS\t(default = %d)\n"
         "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
+        "\t[--max-time|-t] SECONDS\t(max time to give to the run, default = unlimited)\n"
         "\t[--verbose|-v]\t\t(extremely verbose output)\n",
         argv0, host_default, (int)port_default,
         thread_count_default, messages_default);
@@ -410,6 +432,7 @@ main(int argc, char *argv[]) {
     char *colon;
     long total = 0, total_bytes = 0;
     int verbose = 0;
+    int timeout_seconds = -1;
 
     struct host_info hi = {host_default, port_default};
 
@@ -422,10 +445,11 @@ main(int argc, char *argv[]) {
         {"port", required_argument, NULL, 'p'},
         {"clients", required_argument, NULL, 'c'},
         {"messages", required_argument, NULL, 'n'},
+        {"max-time", required_argument, NULL, 't'},
         {"verbose", no_argument, NULL, 'v'},
         {0, 0, 0, 0}
     };
-    while ((opt = getopt_long(argc, argv, "h:p:c:n:vs", long_options, NULL)) != -1) {
+    while ((opt = getopt_long(argc, argv, "h:p:c:n:t:vs", long_options, NULL)) != -1) {
         switch (opt) {
             case 'h':
                 colon = strchr(optarg, ':');
@@ -452,6 +476,10 @@ main(int argc, char *argv[]) {
                 msg_target = atoi(optarg);
                 break;
 
+            case 't':
+                timeout_seconds = atoi(optarg);
+                break;
+
             case 'v':
                 verbose = 1;
                 break;
@@ -468,35 +496,30 @@ main(int argc, char *argv[]) {
     workers = calloc(sizeof(struct worker_thread), thread_count);
 
     clock_gettime(CLOCK_MONOTONIC, &t0);
-    if (thread_count == 1) {
-        printf("Single-threaded mode\n");
-        workers[0].id = 0;
-        workers[0].msg_target = msg_target;
-        workers[0].hi = &hi;
-        workers[0].verbose = verbose;
-        workers[0].state = WS_INITIAL;
-        workers[0].debug = verbose ? debug_verbose : debug_noop;
-        worker_main(&workers[0]);
-        total = workers[0].msg_received;
-        total_bytes = workers[0].byte_count;
-    } else {
-        for (i = 0; i < thread_count; ++i) {
-            workers[i].id = i;
-            workers[i].msg_target = msg_target;
-            workers[i].hi = &hi;
-            workers[i].verbose = verbose;
-            workers[i].state = WS_INITIAL;
-            workers[i].debug = verbose ? debug_verbose : debug_noop;
+    for (i = 0; i < thread_count; ++i) {
+        workers[i].id = i;
+        workers[i].msg_target = msg_target;
+        workers[i].hi = &hi;
+        workers[i].verbose = verbose;
+        workers[i].state = WS_INITIAL;
+        workers[i].debug = verbose ? debug_verbose : debug_noop;
+        workers[i].timeout_seconds = timeout_seconds;
+        if (thread_count == 1) {
+            printf("Single-threaded mode\n");
+            worker_main(&workers[0]);
+        } else { /* create threads */
             pthread_create(&workers[i].thread, NULL,
                            worker_main, &workers[i]);
         }
+    }
 
-        /* wait for threads to finish */
-        for (i = 0; i < thread_count; ++i) {
+    /* wait for threads to finish */
+    for (i = 0; i < thread_count; ++i) {
+        if (thread_count > 1) {
             pthread_join(workers[i].thread, NULL);
-            total += workers[i].msg_received;
-            total_bytes += workers[i].byte_count;
         }
+        total += workers[i].msg_received;
+        total_bytes += workers[i].byte_count;
     }
 
     /* timing */

From b5b76c9c8fcf6edfe85c45664ea92b2665811fdd Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 15:34:44 -0700
Subject: [PATCH 11/28] Reduce default number of websocket messages to test for

2,500 per client with 4 clients: 10,000 total
---
 tests/websocket.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 0151c6f..555be08 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -421,7 +421,7 @@ main(int argc, char *argv[]) {
 
     struct timespec t0, t1;
 
-    int messages_default = 100000;
+    int messages_default = 2500;
     int thread_count_default = 4;
     short port_default = 7379;
     char *host_default = "127.0.0.1";

From a666d52471e28763026f17295d87149d8d1e39fa Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:02:45 -0700
Subject: [PATCH 12/28] Requested changes: logger

* Better log level check
* Add output letter for WEBDIS_TRACE logs
---
 src/slog.c | 19 ++++++++++++++-----
 1 file changed, 14 insertions(+), 5 deletions(-)

diff --git a/src/slog.c b/src/slog.c
index 3a48680..c6d8c00 100644
--- a/src/slog.c
+++ b/src/slog.c
@@ -87,13 +87,11 @@ slog_enabled(struct server *s, log_level level) {
 /**
  * Write log message to disk, or stderr.
  */
-void
-slog(struct server *s, log_level level,
+static void
+slog_internal(struct server *s, log_level level,
 		const char *body, size_t sz) {
 
-	if(level > s->cfg->verbosity) return; /* too verbose */
-
-	const char *c = "EWNID";
+	const char *c = "EWNIDT";
 	time_t now;
 	struct tm now_tm, *lt_ret;
 	char time_buf[64];
@@ -129,3 +127,14 @@ slog(struct server *s, log_level level,
 
 	(void)ret;
 }
+
+/**
+ * This wrapper around slog_internal that first checks the log level.
+ */
+void
+slog(struct server *s, log_level level,
+		const char *body, size_t sz) {
+	if(level <= s->cfg->verbosity) { /* check log level first */
+		slog_internal(s, level, body, sz);
+	}
+}

From c4ac66f78b9d2024361023db0025b6bb72b0e229 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:08:08 -0700
Subject: [PATCH 13/28] Remove extra trace logs in WS-related code

---
 src/http.c      | 20 ------------
 src/websocket.c | 84 +++++++------------------------------------------
 src/worker.c    |  3 --
 3 files changed, 11 insertions(+), 96 deletions(-)

diff --git a/src/http.c b/src/http.c
index da396a8..ef4ea9a 100644
--- a/src/http.c
+++ b/src/http.c
@@ -2,7 +2,6 @@
 #include "server.h"
 #include "worker.h"
 #include "client.h"
-#include "slog.h"
 
 #include <string.h>
 #include <stdlib.h>
@@ -99,12 +98,6 @@ http_response_cleanup(struct http_response *r, int fd, int success) {
 	free(r->out);
 	if(!r->keep_alive || !success) {
 		/* Close fd is client doesn't support Keep-Alive. */
-		if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) {
-			char format[] = "http_response_cleanup: keep_alive=%d, success=%d -> closing";
-			char cleanup_msg[sizeof(format)];
-			snprintf(cleanup_msg, sizeof(cleanup_msg), format, r->keep_alive ? 1 : 0, success ? 1: 0);
-			slog(r->w->s, WEBDIS_TRACE, cleanup_msg, 0);
-		}
 		close(fd);
 	}
 
@@ -131,19 +124,6 @@ http_can_write(int fd, short event, void *p) {
 	if(ret > 0)
 		r->sent += ret;
 
-	if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) { /* trace logs */
-		char format[] = "http_can_write: wrote %d, remaining=%lu, total sent=%d";
-		size_t contents_sz = snprintf(NULL, 0, format, ret, r->out_sz - r->sent, r->sent);
-		char *contents_msg = calloc(contents_sz + 1, 1);
-		if (contents_msg) {
-			snprintf(contents_msg, contents_sz + 1, format, ret, r->out_sz - r->sent, r->sent);
-			slog(r->w->s, WEBDIS_TRACE, contents_msg, contents_sz);
-			free(contents_msg);
-		} else {
-			slog(r->w->s, WEBDIS_ERROR, "Failed allocation in http_can_write", 0);
-		}
-	}
-
 	if(ret <= 0 || r->out_sz - r->sent == 0) { /* error or done */
 		http_response_cleanup(r, fd, (int)r->out_sz == r->sent ? 1 : 0);
 	} else { /* reschedule write */
diff --git a/src/websocket.c b/src/websocket.c
index 8aae00e..cf4995e 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -220,13 +220,12 @@ ws_execute(struct http_client *c, const char *frame, size_t frame_len) {
 }
 
 static struct ws_msg *
-ws_msg_new(struct server *s) {
-	slog(s, WEBDIS_TRACE, "ws_msg_new", 0);
+ws_msg_new() {
 	return calloc(1, sizeof(struct ws_msg));
 }
 
 static void
-ws_msg_add(struct server *s, struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) {
+ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) {
 
 	/* add data to frame */
 	size_t i;
@@ -237,35 +236,21 @@ ws_msg_add(struct server *s, struct ws_msg *m, const char *p, size_t psz, const
 	for(i = 0; i < psz && mask; ++i) {
 		m->payload[m->payload_sz + i] = (unsigned char)p[i] ^ mask[i%4];
 	}
-	if (slog_enabled(s, WEBDIS_TRACE)) {
-		char format[] = "ws_msg_add: %lu bytes, mask_enabled=%c";
-		char mask_enabled = mask ? 'Y' : 'N';
-
-		size_t contents_sz = snprintf(NULL, 0, format, psz, mask_enabled);
-		char *contents_msg = calloc(contents_sz + 1, 1);
-		if (contents_msg) {
-			snprintf(contents_msg, contents_sz + 1, format, psz, mask_enabled);
-			slog(s, WEBDIS_TRACE, contents_msg, contents_sz);
-			free(contents_msg);
-		} else {
-			slog(s, WEBDIS_ERROR, "Failed allocation in ws_msg_add", 0);
-		}
-	}
 
 	/* save new size */
 	m->payload_sz += psz;
 }
 
 static void
-ws_msg_free(struct server *s, struct ws_msg **m) {
-	slog(s, WEBDIS_TRACE, "ws_msg_free", 0);
+ws_msg_free(struct ws_msg **m) {
+
 	free((*m)->payload);
 	free(*m);
 	*m = NULL;
 }
 
 static enum ws_state
-ws_parse_data(struct server *s, const char *frame, size_t sz, struct ws_msg **msg) {
+ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) {
 
 	int has_mask;
 	uint64_t len;
@@ -278,27 +263,9 @@ ws_parse_data(struct server *s, const char *frame, size_t sz, struct ws_msg **ms
 	}
 
 	has_mask = frame[1] & 0x80 ? 1:0;
-	if (slog_enabled(s, WEBDIS_TRACE)) {
-		char log_mask[]= "ws_parse_data: has_mask=?";
-		log_mask[sizeof(log_mask)-2] = has_mask ? 'Y' : 'N'; /* -1 for \0 and -1 again for last char */
-		slog(s, WEBDIS_TRACE, log_mask, sizeof(log_mask)-1);
-	}
 
 	/* get payload length */
 	len = frame[1] & 0x7f;	/* remove leftmost bit */
-
-	if (slog_enabled(s, WEBDIS_TRACE)) { /* log length */
-		char format[] = "ws_parse_data: payload length = %llu bytes";
-		size_t contents_sz = snprintf(NULL, 0, format, len);
-		char *contents_msg = calloc(contents_sz + 1, 1);
-		if (contents_msg) {
-			snprintf(contents_msg, contents_sz + 1, format, len);
-			slog(s, WEBDIS_TRACE, contents_msg, contents_sz);
-			free(contents_msg);
-		} else {
-			slog(s, WEBDIS_ERROR, "Failed allocation in ws_parse_data", 0);
-		}
-	}
 	if(len <= 125) { /* data starts right after the mask */
 		p = frame + 2 + (has_mask ? 4 : 0);
 		if(has_mask) memcpy(&mask, frame + 2, sizeof(mask));
@@ -322,15 +289,13 @@ ws_parse_data(struct server *s, const char *frame, size_t sz, struct ws_msg **ms
 	}
 
 	if(!*msg)
-		*msg = ws_msg_new(s);
-	ws_msg_add(s, *msg, p, len, has_mask ? mask : NULL);
+		*msg = ws_msg_new();
+	ws_msg_add(*msg, p, len, has_mask ? mask : NULL);
 	(*msg)->total_sz += len + (p - frame);
 
 	if(frame[0] & 0x80) { /* FIN bit set */
-		slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit set", 0);
 		return WS_MSG_COMPLETE;
 	} else {
-		slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit not set", 0);
 		return WS_READING;	/* need more data */
 	}
 }
@@ -344,43 +309,30 @@ ws_add_data(struct http_client *c) {
 
 	enum ws_state state;
 
-	state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame);
+	state = ws_parse_data(c->buffer, c->sz, &c->frame);
 
 	while(state == WS_MSG_COMPLETE) {
 		int ret = ws_execute(c, c->frame->payload, c->frame->payload_sz);
-		if (slog_enabled(c->s, WEBDIS_TRACE)) {
-			char format[] = "ws_add_data: ws_execute(payload_sz=%lu) returned %d";
-
-			size_t contents_sz = snprintf(NULL, 0, format, c->frame->payload_sz, ret);
-			char *contents_msg = calloc(contents_sz + 1, 1);
-			if (contents_msg) {
-				snprintf(contents_msg, contents_sz + 1, format, c->frame->payload_sz, ret);
-				slog(c->s, WEBDIS_TRACE, contents_msg, contents_sz);
-				free(contents_msg);
-			} else {
-				slog(c->s, WEBDIS_ERROR, "Failed allocation in ws_add_data", 0);
-			}
-		}
 
 		/* remove frame from client buffer */
 		http_client_remove_data(c, c->frame->total_sz);
 
 		/* free frame and set back to NULL */
-		ws_msg_free(c->s, &c->frame);
+		ws_msg_free(&c->frame);
 
 		if(ret != 0) {
 			/* can't process frame. */
 			slog(c->s, WEBDIS_WARNING, "ws_add_data: ws_execute failed", 0);
 			return WS_ERROR;
 		}
-		slog(c->s, WEBDIS_TRACE, "ws_add_data: calling ws_parse_data again", 0);
-		state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame);
+		state = ws_parse_data(c->buffer, c->sz, &c->frame);
 	}
 	return state;
 }
 
 int
 ws_reply(struct cmd *cmd, const char *p, size_t sz) {
+
 	char *frame = malloc(sz + 8); /* create frame by prepending header */
 	size_t frame_sz = 0;
 	struct http_response *r;
@@ -427,20 +379,6 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) {
 	r->out = frame;
 	r->out_sz = frame_sz;
 	r->sent = 0;
-
-	if (slog_enabled(cmd->w->s, WEBDIS_TRACE)) {
-		char format[] = "ws_reply: response is %lu bytes, frame is %lu";
-		size_t contents_sz = snprintf(NULL, 0, format, sz, frame_sz);
-		char *contents_msg = calloc(contents_sz + 1, 1);
-		if (contents_msg) {
-			snprintf(contents_msg, contents_sz + 1, format, sz, frame_sz);
-			slog(cmd->w->s, WEBDIS_TRACE, contents_msg, contents_sz);
-			free(contents_msg);
-		} else {
-			slog(cmd->w->s, WEBDIS_ERROR, "Failed allocation in ws_reply", 0);
-		}
-	}
-
 	http_schedule_write(cmd->fd, r);
 
 	return 0;
diff --git a/src/worker.c b/src/worker.c
index 747c5ff..964d154 100644
--- a/src/worker.c
+++ b/src/worker.c
@@ -41,7 +41,6 @@ worker_can_read(int fd, short event, void *p) {
 	(void)fd;
 	(void)event;
 
-	slog(c->w->s, WEBDIS_TRACE, "worker_can_read", 0);
 	ret = http_client_read(c);
 	if(ret <= 0) {
 		if((client_error_t)ret == CLIENT_DISCONNECTED) {
@@ -87,11 +86,9 @@ worker_can_read(int fd, short event, void *p) {
 	}
 
 	if(c->broken) { /* terminate client */
-		slog(c->s, WEBDIS_TRACE, "worker_can_read: c->broken, calling http_client_free", 0);
 		http_client_free(c);
 	} else {
 		/* start monitoring input again */
-		slog(c->s, WEBDIS_TRACE, "worker_can_read: calling worker_monitor_input again", 0);
 		worker_monitor_input(c);
 	}
 }

From e97056f4cfe7e06bec532ee7e53ccfd86f35bae7 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:16:23 -0700
Subject: [PATCH 14/28] Add DEBUG=1 logic in tests/Makefile

---
 tests/Makefile | 23 +++++++++++++++++++----
 1 file changed, 19 insertions(+), 4 deletions(-)

diff --git a/tests/Makefile b/tests/Makefile
index be3caa0..861ba4c 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -1,10 +1,25 @@
 OUT=websocket pubsub
-CFLAGS=-O0 -g -Wall -Wextra -I../src/http-parser/
-LDFLAGS=-g -levent -lpthread
+OBJS=../src/http-parser/http_parser.o
+CFLAGS=-Wall -Wextra -I../src/http-parser/
+LDFLAGS=-levent -lpthread
+
+# if `make` is run with DEBUG=1, include debug symbols (same as in Makefile in root directory)
+DEBUG_FLAGS=
+ifeq ($(DEBUG),1)
+	DEBUG_FLAGS += -O0
+	ifeq ($(shell cc -v 2>&1 | grep -cw 'gcc version'),1) # GCC used: add GDB debugging symbols
+		DEBUG_FLAGS += -ggdb3
+	else ifeq ($(shell gcc -v 2>&1 | grep -cw 'clang version'),1) # Clang used: add LLDB debugging symbols
+		DEBUG_FLAGS += -g3 -glldb
+	endif
+else
+	DEBUG_FLAGS += -O3
+endif
+CFLAGS += $(DEBUG_FLAGS)
 
 all: $(OUT) Makefile
 
-websocket: websocket.o ../src/http-parser/http_parser.o
+websocket: websocket.o $(OBJS)
 	$(CC) -o $@ $^ $(LDFLAGS)
 
 pubsub: pubsub.o
@@ -14,5 +29,5 @@ pubsub: pubsub.o
 	$(CC) -c $(CFLAGS) -o $@ $<
 
 clean:
-	rm -f *.o $(OUT)
+	rm -f *.o $(OUT) $(OBJS)
 

From 8141c00ab72ff8662c24974628ab4752cdfda03d Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:43:02 -0700
Subject: [PATCH 15/28] websocket test: formatting/indentation

---
 tests/websocket.c | 847 +++++++++++++++++++++++-----------------------
 1 file changed, 418 insertions(+), 429 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 555be08..e117e8a 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -17,95 +17,98 @@
 #include <event.h>
 #include <http_parser.h>
 
-#define DEBUG_LOGS 0
-
-struct host_info {
-    char *host;
-    short port;
+struct host_info{
+	char *host;
+	short port;
 };
 
 enum worker_state {
-    WS_INITIAL,
-    WS_SENT_HANDSHAKE,
-    WS_RECEIVED_HANDSHAKE,
-    WS_SENT_FRAME,
-    WS_COMPLETE
+	WS_INITIAL,
+	WS_SENT_HANDSHAKE,
+	WS_RECEIVED_HANDSHAKE,
+	WS_SENT_FRAME,
+	WS_COMPLETE
 };
 
 /* worker_thread, with counter of remaining messages */
 struct worker_thread {
-    struct host_info *hi;
-    struct event_base *base;
+	struct host_info *hi;
+	struct event_base *base;
 
-    int msg_target;
-    int msg_received;
-    int msg_sent;
-    int byte_count;
-    int id;
-    pthread_t thread;
-    enum worker_state state;
-    int timeout_seconds;
+	int msg_target;
+	int msg_received;
+	int msg_sent;
+	int byte_count;
+	int id;
+	pthread_t thread;
+	enum worker_state state;
+	int timeout_seconds;
 
-    struct evbuffer *rbuffer;
-    int got_header;
+	struct evbuffer *rbuffer;
+	int got_header;
 
-    struct evbuffer *wbuffer;
+	struct evbuffer *wbuffer;
 
-    int verbose;
-    int fd;
-    struct event ev_r;
-    struct event ev_w;
+	int verbose;
+	int fd;
+	struct event ev_r;
+	struct event ev_w;
 
-    http_parser parser;
-    http_parser_settings settings;
+	http_parser parser;
+	http_parser_settings settings;
 
-    int (*debug)(const char *fmt, ...);
+	int (*debug)(const char *fmt, ...);
 };
 
 int debug_noop(const char *fmt, ...) {
-    (void)fmt;
-    return 0;
+	(void)fmt;
+	return 0;
 }
 
 int debug_verbose(const char *fmt, ...) {
-    int ret;
-    va_list vargs;
-    va_start(vargs, fmt);
-    ret = vfprintf(stderr, fmt, vargs);
-    va_end(vargs);
-    return ret;
+	int ret;
+	va_list vargs;
+	va_start(vargs, fmt);
+	ret = vfprintf(stderr, fmt, vargs);
+	va_end(vargs);
+	return ret;
 }
 
 void
 hex_dump(struct worker_thread *wt, char *p, size_t sz) {
-    wt->debug("hex dump of %p (%ld bytes)\n", p, sz);
-    for (char *cur = p; cur < p + sz; cur += 16) {
-        char letters[16] = {0};
-        int limit = (cur + 16) > p + sz ? (sz % 16) : 16;
-        wt->debug("%08lx ", cur - p); /* address */
-        for (int i = 0; i < limit; i++) {
-            wt->debug("%02x ", (unsigned int)(cur[i] & 0xff));
-            letters[i] = isprint(cur[i]) ? cur[i] : '.';
-        }
-        for (int i = limit; i < 16; i++) { /* pad on last line */
-            wt->debug("   ");
-        }
-        wt->debug(" %.*s\n", limit, letters);
-    }
+	wt->debug("hex dump of %p (%ld bytes)\n", p, sz);
+	for (char *cur = p; cur < p + sz; cur += 16) {
+		char letters[16] = {0};
+		int limit = (cur + 16) > p + sz ? (sz % 16) : 16;
+		wt->debug("%08lx ", cur - p); /* address */
+		for (int i = 0; i < limit; i++) {
+			wt->debug("%02x ", (unsigned int)(cur[i] & 0xff));
+			letters[i] = isprint(cur[i]) ? cur[i] : '.';
+		}
+		for (int i = limit; i < 16; i++) { /* pad on last line */
+			wt->debug("   "); /* 3 spaces for "%02x " */
+		}
+		wt->debug(" %.*s\n", limit, letters);
+	}
 }
 
 void
 evbuffer_debug_dump(struct worker_thread *wt, struct evbuffer *buffer) {
-    size_t sz = evbuffer_get_length(buffer);
-    char *data = malloc(sz);
-    evbuffer_remove(buffer, data, sz);
-    hex_dump(wt, data, sz);
-    evbuffer_prepend(buffer, data, sz);
-    free(data);
+	size_t sz = evbuffer_get_length(buffer);
+	char *data = malloc(sz);
+	if (!data) {
+		fprintf(stderr, "failed to allocate %ld bytes\n", sz);
+		return;
+	}
+	evbuffer_remove(buffer, data, sz);
+	hex_dump(wt, data, sz);
+	evbuffer_prepend(buffer, data, sz);
+	free(data);
 }
 
 static void
 wait_for_possible_read(struct worker_thread *wt);
+
 static void
 wait_for_possible_write(struct worker_thread *wt);
 
@@ -114,22 +117,20 @@ ws_enqueue_frame(struct worker_thread *wt);
 
 void
 process_message(struct worker_thread *wt, size_t sz) {
-
-    // printf("process_message\n");
-    if(wt->msg_received && wt->msg_received % 1000 == 0) {
-        printf("thread %d: %8d messages left (got %9d bytes so far).\n",
-            wt->id,
-            wt->msg_target - wt->msg_received, wt->byte_count);
-    }
-    wt->byte_count += sz;
-
-    /* decrement read count, and stop receiving when we reach zero. */
-    wt->msg_received++;
-    if(wt->msg_received == wt->msg_target) {
-        wt->debug("%s: thread %d has received all %d messages it expected\n",
-            __func__, wt->id, wt->msg_received);
-        event_base_loopexit(wt->base, NULL);
-    }
+	if (wt->msg_received && wt->msg_received % 1000 == 0) {
+		printf("thread %d: %8d messages left (got %9d bytes so far).\n",
+		       wt->id,
+		       wt->msg_target - wt->msg_received, wt->byte_count);
+	}
+	wt->byte_count += sz;
+
+	/* decrement read count, and stop receiving when we reach zero. */
+	wt->msg_received++;
+	if (wt->msg_received == wt->msg_target) {
+		wt->debug("%s: thread %d has received all %d messages it expected\n",
+			  __func__, wt->id, wt->msg_received);
+		event_base_loopexit(wt->base, NULL);
+	}
 }
 
 /**
@@ -137,408 +138,396 @@ process_message(struct worker_thread *wt, size_t sz) {
  */
 void
 websocket_can_write(int fd, short event, void *ptr) {
-    int ret;
-    struct worker_thread *wt = ptr;
-    wt->debug("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
-
-    if(event != EV_WRITE) {
-        return;
-    }
-    switch (wt->state)
-    {
-    case WS_INITIAL: { /* still sending initial HTTP request */
-        ret = evbuffer_write(wt->wbuffer, fd);
-        wt->debug("evbuffer_write returned %d\n", ret);
-        wt->debug("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
-        if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */
-            wait_for_possible_write(wt);
-            return;
-        }
-        /* otherwise, we've sent the full request, time to read the response */
-        wt->state = WS_SENT_HANDSHAKE;
-        wt->debug("state=WS_SENT_HANDSHAKE\n");
-        wait_for_possible_read(wt);
-        return;
-    }
-    case WS_RECEIVED_HANDSHAKE: { /* ready to send a frame */
-        wt->debug("About to send data for WS frame, %lu in buffer\n", evbuffer_get_length(wt->wbuffer));
-        evbuffer_write(wt->wbuffer, fd);
-        size_t write_remains = evbuffer_get_length(wt->wbuffer);
-        wt->debug("Sent data for WS frame, still %lu left to write\n", write_remains);
-        if (write_remains == 0) { /* ready to read response */
-            wt->state = WS_SENT_FRAME;
-            wt->msg_sent++;
-            wait_for_possible_read(wt);
-        } else { /* not finished writing */
-            wait_for_possible_write(wt);
-        }
-        return;
-    }
-    default:
-        break;
-    }
+	int ret;
+	struct worker_thread *wt = ptr;
+	wt->debug("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
+
+	switch (wt->state) {
+	case WS_INITIAL: { /* still sending initial HTTP request */
+		ret = evbuffer_write(wt->wbuffer, fd);
+		wt->debug("evbuffer_write returned %d\n", ret);
+		wt->debug("evbuffer_get_length returned %d\n", evbuffer_get_length(wt->wbuffer));
+		if (evbuffer_get_length(wt->wbuffer) != 0) { /* not all written */
+			wait_for_possible_write(wt);
+			return;
+		}
+		/* otherwise, we've sent the full request, time to read the response */
+		wt->state = WS_SENT_HANDSHAKE;
+		wt->debug("state=WS_SENT_HANDSHAKE\n");
+		wait_for_possible_read(wt);
+		return;
+	}
+	case WS_RECEIVED_HANDSHAKE: { /* ready to send a frame */
+		wt->debug("About to send data for WS frame, %lu in buffer\n", evbuffer_get_length(wt->wbuffer));
+		evbuffer_write(wt->wbuffer, fd);
+		size_t write_remains = evbuffer_get_length(wt->wbuffer);
+		wt->debug("Sent data for WS frame, still %lu left to write\n", write_remains);
+		if (write_remains == 0) { /* ready to read response */
+			wt->state = WS_SENT_FRAME;
+			wt->msg_sent++;
+			wait_for_possible_read(wt);
+		} else { /* not finished writing */
+			wait_for_possible_write(wt);
+		}
+		return;
+	}
+	default:
+		break;
+	}
 }
 
 static void
 websocket_can_read(int fd, short event, void *ptr) {
-    int ret;
-
-    struct worker_thread *wt = ptr;
-    wt->debug("%s (wt=%p)\n", __func__, wt);
-
-    if(event != EV_READ) {
-        return;
-    }
-
-    /* read message */
-    ret = evbuffer_read(wt->rbuffer, fd, 65536);
-    wt->debug("evbuffer_read() returned %d; wt->state=%d. wt->rbuffer:\n", ret, wt->state);
-    evbuffer_debug_dump(wt, wt->rbuffer);
-    if (ret == 0) {
-        wt->debug("We didn't read anything from the socket...\n");
-        return;
-    }
-
-    while(1) {
-        switch (wt->state) {
-        case WS_SENT_HANDSHAKE: { /* waiting for handshake response */
-            size_t avail_sz = evbuffer_get_length(wt->rbuffer);
-            char *tmp = calloc(avail_sz, 1);
-            wt->debug("avail_sz from rbuffer = %lu\n", avail_sz);
-            evbuffer_remove(wt->rbuffer, tmp, avail_sz); /* copy into `tmp` */
-            wt->debug("Giving %lu bytes to http-parser\n", avail_sz);
-            int nparsed = http_parser_execute(&wt->parser, &wt->settings, tmp, avail_sz);
-            wt->debug("http-parser returned %d\n", nparsed);
-            if (nparsed != (int)avail_sz) { // put back what we didn't read
-                wt->debug("re-attach (prepend) %lu byte%c\n", avail_sz - nparsed,
-                          avail_sz - nparsed > 1 ? 's' : ' ');
-                evbuffer_prepend(wt->rbuffer, tmp + nparsed, avail_sz - nparsed);
-            }
-            free(tmp);
-            if (wt->state == WS_SENT_HANDSHAKE &&  /* haven't encountered end of response yet */
-                wt->parser.upgrade && nparsed != (int)avail_sz) {
-                wt->debug("UPGRADE *and* we have some data left\n");
-                continue;
-            } else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
-                evbuffer_drain(wt->rbuffer, evbuffer_get_length(wt->rbuffer));
-            }
-            return;
-        }
-
-        case WS_SENT_FRAME: { /* waiting for frame response */
-            wt->debug("We're in WS_SENT_FRAME, just read a frame response. wt->rbuffer:\n");
-            evbuffer_debug_dump(wt, wt->rbuffer);
-            uint8_t flag_opcodes, payload_len;
-            if (evbuffer_get_length(wt->rbuffer) < 2) { /* not enough data */
-                wait_for_possible_read(wt);
-                return;
-            }
-            evbuffer_remove(wt->rbuffer, &flag_opcodes, 1); /* remove flags & opcode */
-            evbuffer_remove(wt->rbuffer, &payload_len, 1);  /* remove length */
-            evbuffer_drain(wt->rbuffer, (size_t)payload_len); /* remove payload itself */
-            process_message(wt, payload_len);
-
-            if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything */
-                if (wt->msg_received < wt->msg_target) { /* let's write again */
-                    wt->debug("our turn to write again\n");
-                    wt->state = WS_RECEIVED_HANDSHAKE;
-                    ws_enqueue_frame(wt);
-                } /* otherwise, we're done */
-                return;
-            } else {
-                wt->debug("there's still data to consume\n");
-                continue;
-            }
-            return;
-        }
-
-        default:
-            return;
-        }
-    }
+	int ret;
+
+	struct worker_thread *wt = ptr;
+	wt->debug("%s (wt=%p)\n", __func__, wt);
+
+	/* read message */
+	ret = evbuffer_read(wt->rbuffer, fd, 65536);
+	wt->debug("evbuffer_read() returned %d; wt->state=%d. wt->rbuffer:\n", ret, wt->state);
+	evbuffer_debug_dump(wt, wt->rbuffer);
+	if (ret == 0) {
+		wt->debug("We didn't read anything from the socket...\n");
+		event_base_loopexit(wt->base, NULL);
+		return;
+	}
+
+	while (1) {
+		switch (wt->state) {
+		case WS_SENT_HANDSHAKE: { /* waiting for handshake response */
+			size_t avail_sz = evbuffer_get_length(wt->rbuffer);
+			char *tmp = calloc(avail_sz, 1);
+			wt->debug("avail_sz from rbuffer = %lu\n", avail_sz);
+			evbuffer_remove(wt->rbuffer, tmp, avail_sz); /* copy into `tmp` */
+			wt->debug("Giving %lu bytes to http-parser\n", avail_sz);
+			int nparsed = http_parser_execute(&wt->parser, &wt->settings, tmp, avail_sz);
+			wt->debug("http-parser returned %d\n", nparsed);
+			if (nparsed != (int)avail_sz) { // put back what we didn't read
+				wt->debug("re-attach (prepend) %lu byte%c\n", avail_sz - nparsed,
+					  avail_sz - nparsed > 1 ? 's' : ' ');
+				evbuffer_prepend(wt->rbuffer, tmp + nparsed, avail_sz - nparsed);
+			}
+			free(tmp);
+			if (wt->state == WS_SENT_HANDSHAKE && /* haven't encountered end of response yet */
+			    wt->parser.upgrade && nparsed != (int)avail_sz) {
+				wt->debug("UPGRADE *and* we have some data left\n");
+				continue;
+			} else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
+				evbuffer_drain(wt->rbuffer, evbuffer_get_length(wt->rbuffer));
+			}
+			return;
+		}
+
+		case WS_SENT_FRAME: { /* waiting for frame response */
+			wt->debug("We're in WS_SENT_FRAME, just read a frame response. wt->rbuffer:\n");
+			evbuffer_debug_dump(wt, wt->rbuffer);
+			uint8_t flag_opcodes, payload_len;
+			if (evbuffer_get_length(wt->rbuffer) < 2) { /* not enough data */
+				wait_for_possible_read(wt);
+				return;
+			}
+			evbuffer_remove(wt->rbuffer, &flag_opcodes, 1);	  /* remove flags & opcode */
+			evbuffer_remove(wt->rbuffer, &payload_len, 1);	  /* remove length */
+			evbuffer_drain(wt->rbuffer, (size_t)payload_len); /* remove payload itself */
+			process_message(wt, payload_len);
+
+			if (evbuffer_get_length(wt->rbuffer) == 0) { /* consumed everything */
+				if (wt->msg_received < wt->msg_target) { /* let's write again */
+					wt->debug("our turn to write again\n");
+					wt->state = WS_RECEIVED_HANDSHAKE;
+					ws_enqueue_frame(wt);
+				} /* otherwise, we're done */
+				return;
+			} else {
+				wt->debug("there's still data to consume\n");
+				continue;
+			}
+			return;
+		}
+
+		default:
+			return;
+		}
+	}
 }
 
 
 static void
 wait_for_possible_read(struct worker_thread *wt) {
-    wt->debug("%s (wt=%p)\n", __func__, wt);
-    event_set(&wt->ev_r, wt->fd, EV_READ, websocket_can_read, wt);
-    event_base_set(wt->base, &wt->ev_r);
-    event_add(&wt->ev_r, NULL);
+	wt->debug("%s (wt=%p)\n", __func__, wt);
+	event_set(&wt->ev_r, wt->fd, EV_READ, websocket_can_read, wt);
+	event_base_set(wt->base, &wt->ev_r);
+	event_add(&wt->ev_r, NULL);
 }
 
 static void
 wait_for_possible_write(struct worker_thread *wt) {
-    wt->debug("%s (wt=%p)\n", __func__, wt);
-    event_set(&wt->ev_r, wt->fd, EV_WRITE, websocket_can_write, wt);
-    event_base_set(wt->base, &wt->ev_r);
-    event_add(&wt->ev_r, NULL);
+	wt->debug("%s (wt=%p)\n", __func__, wt);
+	event_set(&wt->ev_r, wt->fd, EV_WRITE, websocket_can_write, wt);
+	event_base_set(wt->base, &wt->ev_r);
+	event_add(&wt->ev_r, NULL);
 }
 
 static int
 ws_on_headers_complete(http_parser *p) {
-    struct worker_thread *wt = p->data;
-
-    wt->debug("%s (wt=%p)\n", __func__, wt);
-    // TODO
-    return 0;
+	struct worker_thread *wt = p->data;
+	wt->debug("%s (wt=%p)\n", __func__, wt);
+	return 0;
 }
 
 static void
 ws_enqueue_frame_for_command(struct worker_thread *wt, char *cmd, size_t sz) {
-    unsigned char mask[4];
-    for (int i = 0; i < 4; i++) {
-        mask[i] = rand() & 0xff;
-    }
-    uint8_t len = (uint8_t)(sz); /* (1 << 7) | length. */
-    len |= (1 << 7); /* set masking bit ON */
-
-    for (size_t i = 0; i < sz; i++) {
-        cmd[i] = (cmd[i] ^ mask[i%4]) & 0xff;
-    }
-    /* 0x81 = 10000001b: FIN bit (only one message in the frame), text frame */
-    evbuffer_add(wt->wbuffer, "\x81", 1);
-    evbuffer_add(wt->wbuffer, &len, 1);
-    evbuffer_add(wt->wbuffer, mask, 4);
-    evbuffer_add(wt->wbuffer, cmd, sz);
+	unsigned char mask[4];
+	for (int i = 0; i < 4; i++) {
+		mask[i] = rand() & 0xff;
+	}
+	uint8_t len = (uint8_t)(sz); /* (1 << 7) | length. */
+	len |= (1 << 7);	     /* set masking bit ON */
+
+	for (size_t i = 0; i < sz; i++) {
+		cmd[i] = (cmd[i] ^ mask[i % 4]) & 0xff;
+	}
+	/* 0x81 = 10000001b: FIN bit (only one message in the frame), text frame */
+	evbuffer_add(wt->wbuffer, "\x81", 1);
+	evbuffer_add(wt->wbuffer, &len, 1);
+	evbuffer_add(wt->wbuffer, mask, 4);
+	evbuffer_add(wt->wbuffer, cmd, sz);
 }
 
 static void
 ws_enqueue_frame(struct worker_thread *wt) {
-    char ping_command[] = "[\"PING\"]";
-    ws_enqueue_frame_for_command(wt, ping_command, sizeof(ping_command) - 1);
+	char ping_command[] = "[\"PING\"]";
+	ws_enqueue_frame_for_command(wt, ping_command, sizeof(ping_command) - 1);
 
-    wait_for_possible_write(wt);
+	wait_for_possible_write(wt);
 }
 
 static int
 ws_on_message_complete(http_parser *p) {
-    struct worker_thread *wt = p->data;
+	struct worker_thread *wt = p->data;
 
-    wt->debug("%s (wt=%p)\n", __func__, wt);
-    // we've received the full HTTP response now, so we're ready to send frames
-    wt->state = WS_RECEIVED_HANDSHAKE;
-    ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
-    return 0;
+	wt->debug("%s (wt=%p)\n", __func__, wt);
+	// we've received the full HTTP response now, so we're ready to send frames
+	wt->state = WS_RECEIVED_HANDSHAKE;
+	ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
+	return 0;
 }
 
 static void
 ws_on_timeout(evutil_socket_t fd, short event, void *arg) {
-    struct worker_thread *wt = arg;
-    (void) fd;
-    (void) event;
+	struct worker_thread *wt = arg;
+	(void)fd;
+	(void)event;
 
-    fprintf(stderr, "Time has run out! (thread %d)\n", wt->id);
-    event_base_loopbreak(wt->base); /* break out of event loop */
+	fprintf(stderr, "Time has run out! (thread %d)\n", wt->id);
+	event_base_loopbreak(wt->base); /* break out of event loop */
 }
 
 void*
 worker_main(void *ptr) {
 
-    char ws_template[] = "GET /.json HTTP/1.1\r\n"
-                "Host: %s:%d\r\n"
-                "Connection: Upgrade\r\n"
-                "Upgrade: WebSocket\r\n"
-                "Origin: http://%s:%d\r\n"
-                "Sec-WebSocket-Key: webdis-websocket-test-key\r\n"
-                "\r\n"
-                ;
-
-    struct worker_thread *wt = ptr;
-
-    int ret;
-    int fd;
-    struct sockaddr_in addr;
-    struct timeval timeout_tv;
-    struct event *timeout_ev;
-
-    /* connect socket */
-    fd = socket(AF_INET, SOCK_STREAM, 0);
-    addr.sin_family = AF_INET;
-    addr.sin_port = htons(wt->hi->port);
-    memset(&(addr.sin_addr), 0, sizeof(addr.sin_addr));
-    addr.sin_addr.s_addr = inet_addr(wt->hi->host);
-
-    ret = connect(fd, (struct sockaddr*)&addr, sizeof(struct sockaddr));
-    if(ret != 0) {
-        fprintf(stderr, "connect: ret=%d: %s\n", ret, strerror(errno));
-        return NULL;
-    }
-
-    /* initialize worker thread */
-    wt->fd = fd;
-    wt->base = event_base_new();
-    wt->rbuffer = evbuffer_new();
-    wt->wbuffer = evbuffer_new(); /* write buffer */
-    wt->byte_count = 0;
-    wt->got_header = 0;
-
-    /* add timeout, if set */
-    if (wt->timeout_seconds > 0) {
-        timeout_tv.tv_sec = wt->timeout_seconds;
-        timeout_tv.tv_usec = 0;
-        timeout_ev = event_new(wt->base, -1, EV_TIMEOUT, ws_on_timeout, wt);
-        event_add(timeout_ev, &timeout_tv);
-    }
-
-    /* initialize HTTP parser, to parse the server response */
-    memset(&wt->settings, 0, sizeof(http_parser_settings));
-    wt->settings.on_headers_complete = ws_on_headers_complete;
-    wt->settings.on_message_complete = ws_on_message_complete;
-    http_parser_init(&wt->parser, HTTP_RESPONSE);
-    wt->parser.data = wt;
-
-    /* add GET request to buffer */
-    evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
-                        wt->hi->host, wt->hi->port);
-    wait_for_possible_write(wt); /* request callback */
-
-    /* go! */
-    event_base_dispatch(wt->base);
-    wt->debug("event_base_dispatch returned\n");
-    event_base_free(wt->base);
-    return NULL;
+	char ws_template[] = "GET /.json HTTP/1.1\r\n"
+			     "Host: %s:%d\r\n"
+			     "Connection: Upgrade\r\n"
+			     "Upgrade: WebSocket\r\n"
+			     "Origin: http://%s:%d\r\n"
+			     "Sec-WebSocket-Key: webdis-websocket-test-key\r\n"
+			     "\r\n";
+
+	struct worker_thread *wt = ptr;
+
+	int ret;
+	int fd;
+	struct sockaddr_in addr;
+	struct timeval timeout_tv;
+	struct event *timeout_ev;
+
+	/* connect socket */
+	fd = socket(AF_INET, SOCK_STREAM, 0);
+	addr.sin_family = AF_INET;
+	addr.sin_port = htons(wt->hi->port);
+	memset(&(addr.sin_addr), 0, sizeof(addr.sin_addr));
+	addr.sin_addr.s_addr = inet_addr(wt->hi->host);
+
+	ret = connect(fd, (struct sockaddr *)&addr, sizeof(struct sockaddr));
+	if (ret != 0) {
+		fprintf(stderr, "connect: ret=%d: %s\n", ret, strerror(errno));
+		return NULL;
+	}
+
+	/* initialize worker thread */
+	wt->fd = fd;
+	wt->base = event_base_new();
+	wt->rbuffer = evbuffer_new();
+	wt->wbuffer = evbuffer_new(); /* write buffer */
+	wt->byte_count = 0;
+	wt->got_header = 0;
+
+	/* add timeout, if set */
+	if (wt->timeout_seconds > 0) {
+		timeout_tv.tv_sec = wt->timeout_seconds;
+		timeout_tv.tv_usec = 0;
+		timeout_ev = event_new(wt->base, -1, EV_TIMEOUT, ws_on_timeout, wt);
+		event_add(timeout_ev, &timeout_tv);
+	}
+
+	/* initialize HTTP parser, to parse the server response */
+	memset(&wt->settings, 0, sizeof(http_parser_settings));
+	wt->settings.on_headers_complete = ws_on_headers_complete;
+	wt->settings.on_message_complete = ws_on_message_complete;
+	http_parser_init(&wt->parser, HTTP_RESPONSE);
+	wt->parser.data = wt;
+
+	/* add GET request to buffer */
+	evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
+			    wt->hi->host, wt->hi->port);
+	wait_for_possible_write(wt); /* request callback */
+
+	/* go! */
+	event_base_dispatch(wt->base);
+	wt->debug("event_base_dispatch returned\n");
+	event_base_free(wt->base);
+	return NULL;
 }
 
-void
-usage(const char* argv0, char *host_default, short port_default,
-        int thread_count_default, int messages_default) {
-
-    printf("Usage: %s [options]\n"
-        "Options are:\n"
-        "\t[--host|-h] HOST\t(default = \"%s\")\n"
-        "\t[--port|-p] PORT\t(default = %d)\n"
-        "\t[--clients|-c] THREADS\t(default = %d)\n"
-        "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
-        "\t[--max-time|-t] SECONDS\t(max time to give to the run, default = unlimited)\n"
-        "\t[--verbose|-v]\t\t(extremely verbose output)\n",
-        argv0, host_default, (int)port_default,
-        thread_count_default, messages_default);
+void usage(const char *argv0, char *host_default, short port_default,
+	   int thread_count_default, int messages_default) {
+
+	printf("Usage: %s [options]\n"
+	       "Options are:\n"
+	       "\t[--host|-h] HOST\t(default = \"%s\")\n"
+	       "\t[--port|-p] PORT\t(default = %d)\n"
+	       "\t[--clients|-c] THREADS\t(default = %d)\n"
+	       "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
+	       "\t[--max-time|-t] SECONDS\t(max time to give to the run, default = unlimited)\n"
+	       "\t[--verbose|-v]\t\t(extremely verbose output)\n",
+	       argv0, host_default, (int)port_default,
+	       thread_count_default, messages_default);
 }
 
 int
 main(int argc, char *argv[]) {
 
-    struct timespec t0, t1;
-
-    int messages_default = 2500;
-    int thread_count_default = 4;
-    short port_default = 7379;
-    char *host_default = "127.0.0.1";
-
-    int msg_target = messages_default;
-    int thread_count = thread_count_default;
-    int i, opt;
-    char *colon;
-    long total = 0, total_bytes = 0;
-    int verbose = 0;
-    int timeout_seconds = -1;
-
-    struct host_info hi = {host_default, port_default};
-
-    struct worker_thread *workers;
-
-    /* getopt */
-    struct option long_options[] = {
-        {"help", no_argument, NULL, '?'},
-        {"host", required_argument, NULL, 'h'},
-        {"port", required_argument, NULL, 'p'},
-        {"clients", required_argument, NULL, 'c'},
-        {"messages", required_argument, NULL, 'n'},
-        {"max-time", required_argument, NULL, 't'},
-        {"verbose", no_argument, NULL, 'v'},
-        {0, 0, 0, 0}
-    };
-    while ((opt = getopt_long(argc, argv, "h:p:c:n:t:vs", long_options, NULL)) != -1) {
-        switch (opt) {
-            case 'h':
-                colon = strchr(optarg, ':');
-                if(!colon) {
-                    size_t sz = strlen(optarg);
-                    hi.host = calloc(1 + sz, 1);
-                    strncpy(hi.host, optarg, sz);
-                } else {
-                    hi.host = calloc(1+colon-optarg, 1);
-                    strncpy(hi.host, optarg, colon-optarg);
-                    hi.port = (short)atol(colon+1);
-                }
-                break;
-
-            case 'p':
-                hi.port = (short)atol(optarg);
-                break;
-
-            case 'c':
-                thread_count = atoi(optarg);
-                break;
-
-            case 'n':
-                msg_target = atoi(optarg);
-                break;
-
-            case 't':
-                timeout_seconds = atoi(optarg);
-                break;
-
-            case 'v':
-                verbose = 1;
-                break;
-
-            default: /* '?' */
-                usage(argv[0], host_default, port_default,
-                        thread_count_default,
-                        messages_default);
-                exit(EXIT_SUCCESS);
-        }
-    }
-
-    /* run threads */
-    workers = calloc(sizeof(struct worker_thread), thread_count);
-
-    clock_gettime(CLOCK_MONOTONIC, &t0);
-    for (i = 0; i < thread_count; ++i) {
-        workers[i].id = i;
-        workers[i].msg_target = msg_target;
-        workers[i].hi = &hi;
-        workers[i].verbose = verbose;
-        workers[i].state = WS_INITIAL;
-        workers[i].debug = verbose ? debug_verbose : debug_noop;
-        workers[i].timeout_seconds = timeout_seconds;
-        if (thread_count == 1) {
-            printf("Single-threaded mode\n");
-            worker_main(&workers[0]);
-        } else { /* create threads */
-            pthread_create(&workers[i].thread, NULL,
-                           worker_main, &workers[i]);
-        }
-    }
-
-    /* wait for threads to finish */
-    for (i = 0; i < thread_count; ++i) {
-        if (thread_count > 1) {
-            pthread_join(workers[i].thread, NULL);
-        }
-        total += workers[i].msg_received;
-        total_bytes += workers[i].byte_count;
-    }
-
-    /* timing */
-    clock_gettime(CLOCK_MONOTONIC, &t1);
-    float mili0 = t0.tv_sec * 1000 + t0.tv_nsec / 1000000;
-    float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
-
-    if(total != 0) {
-        double kb_per_sec = ((double)total_bytes / (double)(mili1-mili0)) / 1.024;
-        printf("Read %ld messages (%ld bytes) in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
-            total,
-            total_bytes,
-            (mili1-mili0)/1000.0,
-            1000*((double)total)/(mili1-mili0),
-            kb_per_sec);
-        return (total == thread_count * msg_target ? EXIT_SUCCESS : EXIT_FAILURE);
-    } else {
-        printf("No message was read.\n");
-        return EXIT_FAILURE;
-    }
+	struct timespec t0, t1;
+
+	int messages_default = 2500;
+	int thread_count_default = 4;
+	short port_default = 7379;
+	char *host_default = "127.0.0.1";
+
+	int msg_target = messages_default;
+	int thread_count = thread_count_default;
+	int i, opt;
+	char *colon;
+	long total = 0, total_bytes = 0;
+	int verbose = 0;
+	int timeout_seconds = -1;
+
+	struct host_info hi = {host_default, port_default};
+
+	struct worker_thread *workers;
+
+	/* getopt */
+	struct option long_options[] = {
+	    {"help", no_argument, NULL, '?'},
+	    {"host", required_argument, NULL, 'h'},
+	    {"port", required_argument, NULL, 'p'},
+	    {"clients", required_argument, NULL, 'c'},
+	    {"messages", required_argument, NULL, 'n'},
+	    {"max-time", required_argument, NULL, 't'},
+	    {"verbose", no_argument, NULL, 'v'},
+	    {0, 0, 0, 0}};
+	while ((opt = getopt_long(argc, argv, "h:p:c:n:t:vs", long_options, NULL)) != -1) {
+		switch (opt) {
+		case 'h':
+			colon = strchr(optarg, ':');
+			if (!colon) {
+				size_t sz = strlen(optarg);
+				hi.host = calloc(1 + sz, 1);
+				strncpy(hi.host, optarg, sz);
+			} else {
+				hi.host = calloc(1 + colon - optarg, 1);
+				strncpy(hi.host, optarg, colon - optarg);
+				hi.port = (short)atol(colon + 1);
+			}
+			break;
+
+		case 'p':
+			hi.port = (short)atol(optarg);
+			break;
+
+		case 'c':
+			thread_count = atoi(optarg);
+			break;
+
+		case 'n':
+			msg_target = atoi(optarg);
+			break;
+
+		case 't':
+			timeout_seconds = atoi(optarg);
+			break;
+
+		case 'v':
+			verbose = 1;
+			break;
+
+		default: /* '?' */
+			usage(argv[0], host_default, port_default,
+			      thread_count_default,
+			      messages_default);
+			exit(EXIT_SUCCESS);
+		}
+	}
+
+	/* run threads */
+	workers = calloc(sizeof(struct worker_thread), thread_count);
+
+	clock_gettime(CLOCK_MONOTONIC, &t0);
+	for (i = 0; i < thread_count; ++i) {
+		workers[i].id = i;
+		workers[i].msg_target = msg_target;
+		workers[i].hi = &hi;
+		workers[i].verbose = verbose;
+		workers[i].state = WS_INITIAL;
+		workers[i].debug = verbose ? debug_verbose : debug_noop;
+		workers[i].timeout_seconds = timeout_seconds;
+		if (thread_count == 1) {
+			printf("Single-threaded mode\n");
+			worker_main(&workers[0]);
+		} else { /* create threads */
+			pthread_create(&workers[i].thread, NULL,
+				       worker_main, &workers[i]);
+		}
+	}
+
+	/* wait for threads to finish */
+	for (i = 0; i < thread_count; ++i) {
+		if (thread_count > 1) {
+			pthread_join(workers[i].thread, NULL);
+		}
+		total += workers[i].msg_received;
+		total_bytes += workers[i].byte_count;
+	}
+
+	/* timing */
+	clock_gettime(CLOCK_MONOTONIC, &t1);
+	float mili0 = t0.tv_sec * 1000 + t0.tv_nsec / 1000000;
+	float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
+
+	if (total != 0) {
+		double kb_per_sec = ((double)total_bytes / (double)(mili1 - mili0)) / 1.024;
+		printf("Read %ld messages (%ld bytes) in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
+		       total,
+		       total_bytes,
+		       (mili1 - mili0) / 1000.0,
+		       1000 * ((double)total) / (mili1 - mili0),
+		       kb_per_sec);
+		return (total == thread_count * msg_target ? EXIT_SUCCESS : EXIT_FAILURE);
+	} else {
+		printf("No message was read.\n");
+		return EXIT_FAILURE;
+	}
 }
 

From 9a758c6bcfbac30598062ca48f4ae635b6951fe9 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:45:31 -0700
Subject: [PATCH 16/28] websocket test: make client sockets non-blocking

---
 tests/websocket.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/tests/websocket.c b/tests/websocket.c
index e117e8a..6c90a3b 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -10,6 +10,7 @@
 #include <errno.h>
 #include <ctype.h>
 #include <getopt.h>
+#include <sys/ioctl.h>
 
 #include <sys/types.h>
 #include <sys/socket.h>
@@ -339,6 +340,7 @@ worker_main(void *ptr) {
 
 	int ret;
 	int fd;
+	int int_one = 1;
 	struct sockaddr_in addr;
 	struct timeval timeout_tv;
 	struct event *timeout_ev;
@@ -355,6 +357,11 @@ worker_main(void *ptr) {
 		fprintf(stderr, "connect: ret=%d: %s\n", ret, strerror(errno));
 		return NULL;
 	}
+	ret = ioctl(fd, FIONBIO, &int_one);
+	if (ret != 0) {
+		fprintf(stderr, "ioctl: ret=%d: %s\n", ret, strerror(errno));
+		return NULL;
+	}
 
 	/* initialize worker thread */
 	wt->fd = fd;

From fd8f0b16e0208308064ebc0ee8621d5c7fc0df52 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 21:46:01 -0700
Subject: [PATCH 17/28] websocket test: remove special single-threaded mode

---
 tests/websocket.c | 13 +++----------
 1 file changed, 3 insertions(+), 10 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 6c90a3b..9a49ec2 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -500,20 +500,13 @@ main(int argc, char *argv[]) {
 		workers[i].state = WS_INITIAL;
 		workers[i].debug = verbose ? debug_verbose : debug_noop;
 		workers[i].timeout_seconds = timeout_seconds;
-		if (thread_count == 1) {
-			printf("Single-threaded mode\n");
-			worker_main(&workers[0]);
-		} else { /* create threads */
-			pthread_create(&workers[i].thread, NULL,
-				       worker_main, &workers[i]);
-		}
+		pthread_create(&workers[i].thread, NULL,
+			       worker_main, &workers[i]);
 	}
 
 	/* wait for threads to finish */
 	for (i = 0; i < thread_count; ++i) {
-		if (thread_count > 1) {
-			pthread_join(workers[i].thread, NULL);
-		}
+		pthread_join(workers[i].thread, NULL);
 		total += workers[i].msg_received;
 		total_bytes += workers[i].byte_count;
 	}

From 657197f737b975815ba45984a632c06046da699b Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sat, 17 Jul 2021 22:27:16 -0700
Subject: [PATCH 18/28] websocket test: make WS mask configurable

---
 tests/websocket.c | 64 ++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 55 insertions(+), 9 deletions(-)

diff --git a/tests/websocket.c b/tests/websocket.c
index 9a49ec2..4491616 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -18,7 +18,7 @@
 #include <event.h>
 #include <http_parser.h>
 
-struct host_info{
+struct host_info {
 	char *host;
 	short port;
 };
@@ -31,6 +31,12 @@ enum worker_state {
 	WS_COMPLETE
 };
 
+enum mask_config {
+	MASK_NEVER,
+	MASK_ALWAYS,
+	MASK_ALTERNATE
+};
+
 /* worker_thread, with counter of remaining messages */
 struct worker_thread {
 	struct host_info *hi;
@@ -45,6 +51,10 @@ struct worker_thread {
 	enum worker_state state;
 	int timeout_seconds;
 
+	/* masking */
+	enum mask_config mask_cfg;
+	int mask_applied;
+
 	struct evbuffer *rbuffer;
 	int got_header;
 
@@ -141,6 +151,7 @@ void
 websocket_can_write(int fd, short event, void *ptr) {
 	int ret;
 	struct worker_thread *wt = ptr;
+	(void) event;
 	wt->debug("%s (wt=%p, fd=%d)\n", __func__, wt, fd);
 
 	switch (wt->state) {
@@ -182,6 +193,7 @@ websocket_can_read(int fd, short event, void *ptr) {
 	int ret;
 
 	struct worker_thread *wt = ptr;
+	(void) event;
 	wt->debug("%s (wt=%p)\n", __func__, wt);
 
 	/* read message */
@@ -279,21 +291,35 @@ ws_on_headers_complete(http_parser *p) {
 
 static void
 ws_enqueue_frame_for_command(struct worker_thread *wt, char *cmd, size_t sz) {
+	int include_mask = (wt->mask_cfg == MASK_ALWAYS ||
+		(wt->mask_cfg == MASK_ALTERNATE && wt->msg_sent % 2 == 0)) ? 1 : 0;
+
 	unsigned char mask[4];
-	for (int i = 0; i < 4; i++) {
+	for (int i = 0; include_mask && i < 4; i++) { /* only if mask is needed */
 		mask[i] = rand() & 0xff;
 	}
 	uint8_t len = (uint8_t)(sz); /* (1 << 7) | length. */
-	len |= (1 << 7);	     /* set masking bit ON */
+	if (include_mask) {
+		len |= (1 << 7); /* set masking bit ON */
+	} 
 
-	for (size_t i = 0; i < sz; i++) {
+	/* apply the mask to the payload */
+	for (size_t i = 0; include_mask && i < sz; i++) {
 		cmd[i] = (cmd[i] ^ mask[i % 4]) & 0xff;
 	}
-	/* 0x81 = 10000001b: FIN bit (only one message in the frame), text frame */
+	/* 0x81 = 10000001b:
+		1: FIN bit (meaning there's only one message in the frame),
+		0: RSV1 bit (reserved),
+		0: RSV2 bit (reserved),
+		0: RSV3 bit (reserved),
+		0001: text frame */
 	evbuffer_add(wt->wbuffer, "\x81", 1);
 	evbuffer_add(wt->wbuffer, &len, 1);
-	evbuffer_add(wt->wbuffer, mask, 4);
+	if (include_mask) { /* only include mask in the frame if needed */
+		evbuffer_add(wt->wbuffer, mask, 4);
+	}
 	evbuffer_add(wt->wbuffer, cmd, sz);
+	wt->mask_applied += include_mask;
 }
 
 static void
@@ -407,10 +433,12 @@ void usage(const char *argv0, char *host_default, short port_default,
 	       "\t[--port|-p] PORT\t(default = %d)\n"
 	       "\t[--clients|-c] THREADS\t(default = %d)\n"
 	       "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
+	       "\t[--mask|-m] MASK_CFG\t(%d: always, %d: never, %d: alternate, default = always)\n"
 	       "\t[--max-time|-t] SECONDS\t(max time to give to the run, default = unlimited)\n"
 	       "\t[--verbose|-v]\t\t(extremely verbose output)\n",
 	       argv0, host_default, (int)port_default,
-	       thread_count_default, messages_default);
+	       thread_count_default, messages_default,
+	       MASK_ALWAYS, MASK_NEVER, MASK_ALTERNATE);
 }
 
 int
@@ -430,6 +458,7 @@ main(int argc, char *argv[]) {
 	long total = 0, total_bytes = 0;
 	int verbose = 0;
 	int timeout_seconds = -1;
+	enum mask_config mask_cfg = MASK_ALWAYS;
 
 	struct host_info hi = {host_default, port_default};
 
@@ -442,10 +471,11 @@ main(int argc, char *argv[]) {
 	    {"port", required_argument, NULL, 'p'},
 	    {"clients", required_argument, NULL, 'c'},
 	    {"messages", required_argument, NULL, 'n'},
+	    {"mask", required_argument, NULL, 'm'},
 	    {"max-time", required_argument, NULL, 't'},
 	    {"verbose", no_argument, NULL, 'v'},
 	    {0, 0, 0, 0}};
-	while ((opt = getopt_long(argc, argv, "h:p:c:n:t:vs", long_options, NULL)) != -1) {
+	while ((opt = getopt_long(argc, argv, "h:p:c:n:m:t:vs", long_options, NULL)) != -1) {
 		switch (opt) {
 		case 'h':
 			colon = strchr(optarg, ':');
@@ -472,6 +502,15 @@ main(int argc, char *argv[]) {
 			msg_target = atoi(optarg);
 			break;
 
+		case 'm':
+			mask_cfg = atoi(optarg);
+			if (mask_cfg < MASK_NEVER || mask_cfg > MASK_ALTERNATE) {
+				fprintf(stderr, "Invalid mask configuration: %d (range is [%d .. %d])\n",
+					mask_cfg, MASK_NEVER, MASK_ALTERNATE);
+				exit(EXIT_FAILURE);
+			}
+			break;
+
 		case 't':
 			timeout_seconds = atoi(optarg);
 			break;
@@ -500,6 +539,7 @@ main(int argc, char *argv[]) {
 		workers[i].state = WS_INITIAL;
 		workers[i].debug = verbose ? debug_verbose : debug_noop;
 		workers[i].timeout_seconds = timeout_seconds;
+		workers[i].mask_cfg = mask_cfg;
 		pthread_create(&workers[i].thread, NULL,
 			       worker_main, &workers[i]);
 	}
@@ -517,9 +557,15 @@ main(int argc, char *argv[]) {
 	float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
 
 	if (total != 0) {
+		int total_masked = 0;
+		for (i = 0; i < thread_count; ++i) {
+			total_masked += workers[i].mask_applied;
+		}
+
 		double kb_per_sec = ((double)total_bytes / (double)(mili1 - mili0)) / 1.024;
-		printf("Read %ld messages (%ld bytes) in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
+		printf("Sent+received %ld messages (%d sent masked) for a total of %ld bytes in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
 		       total,
+		       total_masked,
 		       total_bytes,
 		       (mili1 - mili0) / 1000.0,
 		       1000 * ((double)total) / (mili1 - mili0),

From d5dc3d3ff056056b68d387678185a4b506eefaa3 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 09:41:27 -0700
Subject: [PATCH 19/28] Add more error-checking to WS handshake code

---
 src/websocket.c | 18 +++++++++++++++---
 1 file changed, 15 insertions(+), 3 deletions(-)

diff --git a/src/websocket.c b/src/websocket.c
index cf4995e..4a41ae0 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -48,7 +48,15 @@ ws_compute_handshake(struct http_client *c, char *out, size_t *out_sz) {
 	// websocket handshake
 	const char *key = client_get_header(c, "Sec-WebSocket-Key");
 	size_t key_sz = key?strlen(key):0, buffer_sz = key_sz + sizeof(magic) - 1;
+	if(!key || key_sz < 16 || key_sz > 32) { /* supposed to be exactly 16 bytes that were b64 encoded */
+		slog(c->s, WEBDIS_WARNING, "Invalid Sec-WebSocket-Key", 0);
+		return -1;
+	}
 	buffer = calloc(buffer_sz, 1);
+	if(!buffer) {
+		slog(c->s, WEBDIS_ERROR, "Failed to allocate memory for WS header", 0);
+		return -1;
+	}
 
 	// concatenate key and guid in buffer
 	memcpy(buffer, key, key_sz);
@@ -58,10 +66,10 @@ ws_compute_handshake(struct http_client *c, char *out, size_t *out_sz) {
 	SHA1Reset(&ctx);
 	SHA1Input(&ctx, buffer, buffer_sz);
 	SHA1Result(&ctx);
-	for(i = 0; i < 5; ++i) {	// put in correct byte order before memcpy.
+	for(i = 0; i < (int)(20/sizeof(int)); ++i) {	// put in correct byte order before memcpy.
 		ctx.Message_Digest[i] = ntohl(ctx.Message_Digest[i]);
 	}
-	memcpy(sha1_output, (unsigned char*)ctx.Message_Digest, 20);
+	memcpy(sha1_output, ctx.Message_Digest, 20);
 
 	// encode `sha1_output' in base 64, into `out'.
 	base64_init_encodestate(&b64_ctx);
@@ -126,6 +134,10 @@ ws_handshake_reply(struct http_client *c) {
 		+ sizeof(template4)-1;
 
 	p = buffer = malloc(sz);
+	if(!p) {
+		slog(c->s, WEBDIS_ERROR, "Failed to allocate memory for WS handshake", 0);
+		return -1;
+	}
 
 	/* Concat all */
 
@@ -160,7 +172,7 @@ ws_handshake_reply(struct http_client *c) {
 	p += sizeof(template4)-1;
 
 	/* send data to client */
-	ret = write(c->fd, buffer, sz);
+	ret = write(c->fd, buffer, sz); /* FIXME: this needs to use the event loop */
 	(void)ret;
 	free(buffer);
 

From 3984fb968fffe4e956de7ae4a79d721b6e7e337c Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 15:18:28 -0700
Subject: [PATCH 20/28] Validate Sec-WebSocket-Accept in WS test

1. Generate random WS connection key
2. Read headers returned in WS connection (upgrade) response
3. Validate Sec-WebSocket-Accept return value from webdis

Tested by introducing an artificial error in webdis, reported as
expected.
---
 tests/Makefile    |   4 +-
 tests/websocket.c | 150 ++++++++++++++++++++++++++++++++++++++++++----
 2 files changed, 140 insertions(+), 14 deletions(-)

diff --git a/tests/Makefile b/tests/Makefile
index 861ba4c..b2fa1f3 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -1,6 +1,6 @@
 OUT=websocket pubsub
-OBJS=../src/http-parser/http_parser.o
-CFLAGS=-Wall -Wextra -I../src/http-parser/
+OBJS=../src/http-parser/http_parser.o ../src/b64/cencode.o ../src/sha1/sha1.o
+CFLAGS=-Wall -Wextra -I../src -I../src/http-parser
 LDFLAGS=-levent -lpthread
 
 # if `make` is run with DEBUG=1, include debug symbols (same as in Makefile in root directory)
diff --git a/tests/websocket.c b/tests/websocket.c
index 4491616..38f475e 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -11,12 +11,14 @@
 #include <ctype.h>
 #include <getopt.h>
 #include <sys/ioctl.h>
+#include <b64/cencode.h>
+#include <http-parser/http_parser.h>
+#include <sha1/sha1.h>
 
 #include <sys/types.h>
 #include <sys/socket.h>
 
 #include <event.h>
-#include <http_parser.h>
 
 struct host_info {
 	char *host;
@@ -51,10 +53,24 @@ struct worker_thread {
 	enum worker_state state;
 	int timeout_seconds;
 
+	/* non-encoded websocket key */
+	char ws_key[16];
+	/* expected response */
+	char ws_response[28];
+	size_t ws_response_len;
+	/* actual response */
+	char *sec_websocket_accept;
 	/* masking */
 	enum mask_config mask_cfg;
 	int mask_applied;
 
+	/* current header */
+	char *cur_hdr_key;
+	size_t cur_hdr_key_len; /* not including trailing \0 */
+	char *cur_hdr_val;
+	size_t cur_hdr_val_len; /* not including trailing \0 */
+	int hdr_last_cb_was_name; /* tells us if the last call was header name or value */
+
 	struct evbuffer *rbuffer;
 	int got_header;
 
@@ -216,14 +232,12 @@ websocket_can_read(int fd, short event, void *ptr) {
 			wt->debug("Giving %lu bytes to http-parser\n", avail_sz);
 			int nparsed = http_parser_execute(&wt->parser, &wt->settings, tmp, avail_sz);
 			wt->debug("http-parser returned %d\n", nparsed);
-			if (nparsed != (int)avail_sz) { // put back what we didn't read
-				wt->debug("re-attach (prepend) %lu byte%c\n", avail_sz - nparsed,
-					  avail_sz - nparsed > 1 ? 's' : ' ');
-				evbuffer_prepend(wt->rbuffer, tmp + nparsed, avail_sz - nparsed);
-			}
 			free(tmp);
-			if (wt->state == WS_SENT_HANDSHAKE && /* haven't encountered end of response yet */
-			    wt->parser.upgrade && nparsed != (int)avail_sz) {
+			/* http parser will return the offset at which the upgraded protocol begins,
+			   which in our case is 1 under the total response size. */
+
+			if (wt->state == WS_SENT_HANDSHAKE || /* haven't encountered end of response yet */
+			    (wt->parser.upgrade && nparsed != (int)avail_sz -1)) {
 				wt->debug("UPGRADE *and* we have some data left\n");
 				continue;
 			} else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
@@ -282,11 +296,81 @@ wait_for_possible_write(struct worker_thread *wt) {
 	event_add(&wt->ev_r, NULL);
 }
 
+static int
+ws_on_header_field(http_parser *p, const char *at, size_t length) {
+	(void)length;
+	struct worker_thread *wt = (struct worker_thread *)p->data;
+
+	if (wt->hdr_last_cb_was_name) { /* we're appending to the name */
+		wt->cur_hdr_key = realloc(wt->cur_hdr_key, wt->cur_hdr_key_len + length + 1);
+		memcpy(wt->cur_hdr_key + wt->cur_hdr_key_len, at, length);
+		wt->cur_hdr_key_len += length;
+	} else { /* first call for this header name */
+		free(wt->cur_hdr_key); /* free the previous header name if there was one */
+		wt->cur_hdr_key_len = length;
+		wt->cur_hdr_key = calloc(length + 1, 1);
+		memcpy(wt->cur_hdr_key, at, length);
+	}
+	wt->debug("%s appended header name data: currently [%.*s]\n", __func__,
+		  (int)wt->cur_hdr_key_len, wt->cur_hdr_key);
+	// wt->cur_header_is_ws_resp = (strncasecmp(at, "Sec-WebSocket-Accept", 20) == 0) ? 1 : 0;
+
+	wt->hdr_last_cb_was_name = 1;
+	return 0;
+}
+
+static int
+ws_on_header_value(http_parser *p, const char *at, size_t length) {
+	struct worker_thread *wt = (struct worker_thread *)p->data;
+
+	if (wt->hdr_last_cb_was_name == 0) { /* we're appending to the value */
+		wt->cur_hdr_val = realloc(wt->cur_hdr_val, wt->cur_hdr_val_len + length + 1);
+		memcpy(wt->cur_hdr_val + wt->cur_hdr_val_len, at, length);
+		wt->cur_hdr_val_len += length;
+	} else { /* first call for this header value */
+		free(wt->cur_hdr_val); /* free the previous header value if there was one */
+		wt->cur_hdr_val_len = length;
+		wt->cur_hdr_val = calloc(length + 1, 1);
+		memcpy(wt->cur_hdr_val, at, length);
+	}
+	wt->debug("%s appended header value data: currently [%.*s]\n", __func__,
+		  (int)wt->cur_hdr_val_len, wt->cur_hdr_val);
+
+	if (wt->cur_hdr_key_len == 20 && strncasecmp(wt->cur_hdr_key, "Sec-WebSocket-Accept", 20) == 0) {
+		free(wt->sec_websocket_accept);
+		wt->sec_websocket_accept = calloc(wt->cur_hdr_val_len + 1, 1);
+		memcpy(wt->sec_websocket_accept, wt->cur_hdr_val, wt->cur_hdr_val_len);
+	}
+
+	wt->hdr_last_cb_was_name = 0;
+	return 0;
+}
+
+
 static int
 ws_on_headers_complete(http_parser *p) {
 	struct worker_thread *wt = p->data;
 	wt->debug("%s (wt=%p)\n", __func__, wt);
-	return 0;
+	free(wt->cur_hdr_key);
+	free(wt->cur_hdr_val);
+
+	/* make sure that we received a Sec-WebSocket-Accept header */
+	if (!wt->sec_websocket_accept) {
+		wt->debug("%s: no Sec-WebSocket-Accept header was returned\n", __func__);
+		return 1;
+	}
+
+	/* and that it matches what we expect */
+	int ret = 0;
+	if (strlen(wt->sec_websocket_accept) != wt->ws_response_len
+		|| memcmp(wt->ws_response, wt->sec_websocket_accept, wt->ws_response_len) != 0) {
+		wt->debug("Invalid WS handshake: expected [%.*s], got [%s]\n",
+			(int)wt->ws_response_len, wt->ws_response, wt->sec_websocket_accept);
+		ret = 1;
+	}
+
+	free(wt->sec_websocket_accept);
+	return ret;
 }
 
 static void
@@ -334,7 +418,7 @@ static int
 ws_on_message_complete(http_parser *p) {
 	struct worker_thread *wt = p->data;
 
-	wt->debug("%s (wt=%p)\n", __func__, wt);
+	wt->debug("%s (wt=%p), upgrade=%d\n", __func__, wt, p->upgrade);
 	// we've received the full HTTP response now, so we're ready to send frames
 	wt->state = WS_RECEIVED_HANDSHAKE;
 	ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
@@ -359,7 +443,7 @@ worker_main(void *ptr) {
 			     "Connection: Upgrade\r\n"
 			     "Upgrade: WebSocket\r\n"
 			     "Origin: http://%s:%d\r\n"
-			     "Sec-WebSocket-Key: webdis-websocket-test-key\r\n"
+			     "Sec-WebSocket-Key: %s\r\n"
 			     "\r\n";
 
 	struct worker_thread *wt = ptr;
@@ -397,6 +481,46 @@ worker_main(void *ptr) {
 	wt->byte_count = 0;
 	wt->got_header = 0;
 
+	/* generate a random key */
+	for (int i = 0; i < 16; i++) {
+		wt->ws_key[i] = rand() & 0xff;
+	}
+	wt->debug("Raw WS key:\n");
+	hex_dump(wt, wt->ws_key, 16);
+
+	char encoded_key[23]; /* it shouldn't be more than 4/3 * 16 */
+	base64_encodestate b64state;
+	base64_init_encodestate(&b64state);
+	int pos = base64_encode_block((const char *)wt->ws_key, 16, encoded_key, &b64state);
+	int delta = base64_encode_blockend(encoded_key + pos, &b64state);
+	/* the block ends with a '\n', which we need to remove */
+	encoded_key[pos+delta-1] = '\0';
+	wt->debug("Encoded WS key [%s]:\n", encoded_key);
+
+	/* compute the expected response, to be validated when we receive it */
+	char magic[] = "258EAFA5-E914-47DA-95CA-C5AB0DC85B11";
+	size_t expected_raw_sz = (pos+delta-1) + sizeof(magic)-1;
+	char *expected_raw = calloc(expected_raw_sz + 1, 1);
+	memcpy(expected_raw, encoded_key, pos+delta-1); /* add encoded key */
+	memcpy(expected_raw + pos+delta-1, magic, sizeof(magic)-1); /* then constant guid */
+
+	SHA1Context ctx;
+	SHA1Reset(&ctx);
+	SHA1Input(&ctx, (const unsigned char*)expected_raw, expected_raw_sz);
+	SHA1Result(&ctx);
+	for(int i = 0; i < (int)(20/sizeof(int)); ++i) { /* put in correct byte order */
+		ctx.Message_Digest[i] = ntohl(ctx.Message_Digest[i]);
+	}
+
+	/* and then base64 encode the hash */
+	base64_init_encodestate(&b64state);
+	int resp_pos = base64_encode_block((const char *)ctx.Message_Digest, 20, wt->ws_response, &b64state);
+	int resp_delta = base64_encode_blockend(wt->ws_response + resp_pos, &b64state);
+	wt->ws_response_len = resp_pos + resp_delta - 1;
+	wt->ws_response[wt->ws_response_len] = '\0'; /* again remove the '\n' */
+
+	wt->debug("Expected response header: [%s]\n", wt->ws_response);
+
 	/* add timeout, if set */
 	if (wt->timeout_seconds > 0) {
 		timeout_tv.tv_sec = wt->timeout_seconds;
@@ -407,6 +531,8 @@ worker_main(void *ptr) {
 
 	/* initialize HTTP parser, to parse the server response */
 	memset(&wt->settings, 0, sizeof(http_parser_settings));
+	wt->settings.on_header_field = ws_on_header_field;
+	wt->settings.on_header_value = ws_on_header_value;
 	wt->settings.on_headers_complete = ws_on_headers_complete;
 	wt->settings.on_message_complete = ws_on_message_complete;
 	http_parser_init(&wt->parser, HTTP_RESPONSE);
@@ -414,7 +540,7 @@ worker_main(void *ptr) {
 
 	/* add GET request to buffer */
 	evbuffer_add_printf(wt->wbuffer, ws_template, wt->hi->host, wt->hi->port,
-			    wt->hi->host, wt->hi->port);
+			    wt->hi->host, wt->hi->port, encoded_key);
 	wait_for_possible_write(wt); /* request callback */
 
 	/* go! */

From e45779b303c8a44d0a7d5419a69fd62d1da2fab9 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 15:26:48 -0700
Subject: [PATCH 21/28] Change TRACE log level to a value greater than was ever
 in webdis.json

---
 src/slog.c | 3 ++-
 src/slog.h | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/src/slog.c b/src/slog.c
index c6d8c00..cae6d9a 100644
--- a/src/slog.c
+++ b/src/slog.c
@@ -116,8 +116,9 @@ slog_internal(struct server *s, log_level level,
 	}
 
 	/* generate output line. */
+	char letter = (level == WEBDIS_TRACE ? 5 : c[level]);
 	line_sz = snprintf(line, sizeof(line),
-		"[%d] %s %c %s\n", (int)s->log.self, time_buf, c[level], msg);
+		"[%d] %s %c %s\n", (int)s->log.self, time_buf, letter, msg);
 
 	/* write to log and maybe flush to disk. */
 	ret = write(s->log.fd, line, line_sz);
diff --git a/src/slog.h b/src/slog.h
index 9400702..14d9c66 100644
--- a/src/slog.h
+++ b/src/slog.h
@@ -7,7 +7,7 @@ typedef enum {
 	WEBDIS_NOTICE,
 	WEBDIS_INFO,
 	WEBDIS_DEBUG,
-	WEBDIS_TRACE
+	WEBDIS_TRACE = 8
 } log_level;
 
 typedef enum {

From 05a90b7b7a96d4a7a0502d46f8adce2d7c7a4691 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 15:38:28 -0700
Subject: [PATCH 22/28] Add "PING" button to HTML demo

---
 tests/websocket.html | 29 ++++++++++++++++++++++++++++-
 1 file changed, 28 insertions(+), 1 deletion(-)

diff --git a/tests/websocket.html b/tests/websocket.html
index 049ff00..77ee9db 100644
--- a/tests/websocket.html
+++ b/tests/websocket.html
@@ -55,6 +55,14 @@
 						</div>
 					</fieldset>
 				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-2-3">&nbsp;</div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-ping">Ping</button></div>
+						</div>
+					</fieldset>
+				</form>
 				<form class="pure-form">
 					<fieldset>
 						<div class="pure-g">
@@ -95,6 +103,14 @@
 						</div>
 					</fieldset>
 				</form>
+				<form class="pure-form">
+					<fieldset>
+						<div class="pure-g">
+							<div class="pure-u-2-3">&nbsp;</div>
+							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-ping">Ping</button></div>
+						</div>
+					</fieldset>
+				</form>
 				<form class="pure-form">
 					<fieldset>
 						<div class="pure-g">
@@ -132,8 +148,9 @@ const host = "127.0.0.1";
 const port = 7379;
 
 class Client {
-	constructor(type, getSerializer, setSerializer) {
+	constructor(type, pingSerializer, getSerializer, setSerializer) {
 		this.type = type;
+		this.pingSerializer = pingSerializer;
 		this.getSerializer = getSerializer;
 		this.setSerializer = setSerializer;
 		this.ws = null;
@@ -158,6 +175,13 @@ class Client {
 			};
 		});
 
+		$(`${this.type}-btn-ping`).addEventListener('click', event => {
+			event.preventDefault();
+			const serialized = this.pingSerializer();
+			this.log("sent", serialized);
+			this.ws.send(serialized);
+		});
+
 		$(`${this.type}-btn-set`).addEventListener('click', event => {
 			event.preventDefault();
 			const serialized = this.setSerializer($(`${this.type}-set-key`).value, $(`${this.type}-set-value`).value);
@@ -180,6 +204,7 @@ class Client {
 
 	setConnectedState(connected) {
 		$(`${this.type}-btn-connect`).disabled = connected;
+		$(`${this.type}-btn-ping`).disabled = !connected;
 		$(`${this.type}-set-key`).disabled = !connected;
 		$(`${this.type}-set-value`).disabled = !connected;
 		$(`${this.type}-btn-set`).disabled = !connected;
@@ -205,10 +230,12 @@ class Client {
 
 addEventListener("DOMContentLoaded", () => {
 	const jsonClient = new Client('json',
+		() => JSON.stringify(['PING']),
 		(key) => JSON.stringify(['GET', key]),
 		(key, value) => JSON.stringify(['SET', key, value]));
 
 	const rawClient = new Client('raw',
+		() => '*1\r\n$4\r\nPING\r\n',
 		(key) => `*2\r\n$3\r\nGET\r\n$${key.length}\r\n${key}\r\n`,
 		(key, value) =>  `*3\r\n$3\r\nSET\r\n$${key.length}\r\n${key}\r\n$${value.length}\r\n${value}\r\n`);
 });

From 4c0d3f403232868e93203495bbc2366aa2373af0 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 15:46:30 -0700
Subject: [PATCH 23/28] Refactor websocket.html to remove duplicate HTML

---
 tests/websocket.html | 146 +++++++++++++++++--------------------------
 1 file changed, 57 insertions(+), 89 deletions(-)

diff --git a/tests/websocket.html b/tests/websocket.html
index 77ee9db..0f06fc8 100644
--- a/tests/websocket.html
+++ b/tests/websocket.html
@@ -45,108 +45,73 @@
 
 		<div class="pure-g">
 			<div class="pure-u-1-8"></div>
-			<div class="pure-u-1-3">
-				<h3>JSON</h3>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-2-3"><label class="ws-state pure-u-23-24" id="json-state">State: Disconnected</label></div>
-							<div class="pure-u-1-3"><button type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-connect">Connect</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-2-3">&nbsp;</div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-ping">Ping</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="json-set-key" value="hello" /></div>
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="value" id="json-set-value" value="world" /></div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-set">SET</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-1-3">&nbsp;</div>
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="json-get-key" value="hello" /></div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-get">GET</button></div>
-						</div>
-					</fieldset>
-				</form>
-
-				<div class="pure-g">
-					<div class="pure-u-2-3">&nbsp;</div>
-					<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="json-btn-clear">Clear logs</button></div>
-					<div class="log pure-u-1-1" id="json-log">
-					</div>
-				</div>
-			</div>
+			<div class="pure-u-1-3" id="json-container"></div>
 
 			<!-- spacer -->
 			<div class="pure-u-1-12"></div>
 
-			<div class="pure-u-1-3">
-				<h3>Raw</h3>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-2-3"><label class="ws-state pure-u-23-24" id="raw-state">State: Disconnected</label></div>
-							<div class="pure-u-1-3"><button type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-connect">Connect</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-2-3">&nbsp;</div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-ping">Ping</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="raw-set-key" value="hello" /></div>
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="value" id="raw-set-value" value="world" /></div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-set">SET</button></div>
-						</div>
-					</fieldset>
-				</form>
-				<form class="pure-form">
-					<fieldset>
-						<div class="pure-g">
-							<div class="pure-u-1-3">&nbsp;</div>
-							<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="raw-get-key" value="hello" /></div>
-							<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-get">GET</button></div>
-						</div>
-					</fieldset>
-				</form>
-
-				<div class="pure-g">
-					<div class="pure-u-2-3">&nbsp;</div>
-					<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="raw-btn-clear">Clear logs</button></div>
-					<div class="log pure-u-1-1" id="raw-log">
-					</div>
-				</div>
-			</div>
-
+			<div class="pure-u-1-3" id="raw-container"></div>
 			<div class="pure-u-1-8"></div>
 		</div>
 
+<script type="text/javascript">
+</script>
+
 <script type="text/javascript">
 
 $ = function(id) {return document.getElementById(id);};
 const host = "127.0.0.1";
 const port = 7379;
 
+function installBlock(title, type) {
+	const contents = `
+	<h3>$TITLE</h3>
+	<form class="pure-form">
+		<fieldset>
+			<div class="pure-g">
+				<div class="pure-u-2-3"><label class="ws-state pure-u-23-24" id="$type-state">State: Disconnected</label></div>
+				<div class="pure-u-1-3"><button type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="$type-btn-connect">Connect</button></div>
+			</div>
+		</fieldset>
+	</form>
+	<form class="pure-form">
+		<fieldset>
+			<div class="pure-g">
+				<div class="pure-u-2-3">&nbsp;</div>
+				<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="$type-btn-ping">Ping</button></div>
+			</div>
+		</fieldset>
+	</form>
+	<form class="pure-form">
+		<fieldset>
+			<div class="pure-g">
+				<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="$type-set-key" value="hello" /></div>
+				<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="value" id="$type-set-value" value="world" /></div>
+				<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="$type-btn-set">SET</button></div>
+			</div>
+		</fieldset>
+	</form>
+	<form class="pure-form">
+		<fieldset>
+			<div class="pure-g">
+				<div class="pure-u-1-3">&nbsp;</div>
+				<div class="pure-u-1-3"><input disabled class="pure-u-23-24" type="text" placeholder="key" id="$type-get-key" value="hello" /></div>
+				<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="$type-btn-get">GET</button></div>
+			</div>
+		</fieldset>
+	</form>
+
+	<div class="pure-g">
+		<div class="pure-u-2-3">&nbsp;</div>
+		<div class="pure-u-1-3"><button disabled type="submit" class="pure-u-23-24 pure-button pure-button-primary" id="$type-btn-clear">Clear logs</button></div>
+		<div class="log pure-u-1-1" id="$type-log">
+		</div>
+	</div>
+	`;
+	$(`${type}-container`).innerHTML = contents.replace(/\$TITLE/g, title).replace(/\$type/g, type);
+}
+
+
 class Client {
 	constructor(type, pingSerializer, getSerializer, setSerializer) {
 		this.type = type;
@@ -229,6 +194,9 @@ class Client {
 }
 
 addEventListener("DOMContentLoaded", () => {
+	installBlock('JSON', 'json');
+	installBlock('Raw', 'raw');
+
 	const jsonClient = new Client('json',
 		() => JSON.stringify(['PING']),
 		(key) => JSON.stringify(['GET', key]),

From 8f70db179f516034666e7e2a7bf2ef8d080ece57 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 16:49:13 -0700
Subject: [PATCH 24/28] Send WS handshake using event loop instead of write(2)

ws_handshake_reply was sending its response using a single write(2) call
without error-checking, which could well send only part of it and leave
the client hanging. This change creates an HTTP response object and
schedules it for writing using the event loop.

Tested with Valgrind, no memory is leaked.
---
 src/websocket.c | 20 ++++++++++++++------
 1 file changed, 14 insertions(+), 6 deletions(-)

diff --git a/src/websocket.c b/src/websocket.c
index 4a41ae0..861605c 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -89,7 +89,6 @@ ws_compute_handshake(struct http_client *c, char *out, size_t *out_sz) {
 int
 ws_handshake_reply(struct http_client *c) {
 
-	int ret;
 	char sha1_handshake[40];
 	char *buffer = NULL, *p;
 	const char *origin = NULL, *host = NULL;
@@ -135,7 +134,7 @@ ws_handshake_reply(struct http_client *c) {
 
 	p = buffer = malloc(sz);
 	if(!p) {
-		slog(c->s, WEBDIS_ERROR, "Failed to allocate memory for WS handshake", 0);
+		slog(c->s, WEBDIS_ERROR, "Failed to allocate buffer for WS handshake", 0);
 		return -1;
 	}
 
@@ -171,10 +170,19 @@ ws_handshake_reply(struct http_client *c) {
 	memcpy(p, template4, sizeof(template4)-1);
 	p += sizeof(template4)-1;
 
-	/* send data to client */
-	ret = write(c->fd, buffer, sz); /* FIXME: this needs to use the event loop */
-	(void)ret;
-	free(buffer);
+	/* build HTTP response object by hand, since we have the full response already */
+	struct http_response *r = calloc(1, sizeof(struct http_response));
+	if(!r) {
+		slog(c->s, WEBDIS_ERROR, "Failed to allocate response for WS handshake", 0);
+		free(buffer);
+		return -1;
+	}
+	r->w = c->w;
+	r->keep_alive = 1;
+	r->out = buffer;
+	r->out_sz = sz;
+	r->sent = 0;
+	http_schedule_write(c->fd, r); /* will free buffer and response once sent */
 
 	return 0;
 }

From 273e2a918df039cc3c5e21a5b39353ff6cab976b Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 17:31:58 -0700
Subject: [PATCH 25/28] Log on WS client error

---
 src/websocket.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/websocket.c b/src/websocket.c
index 861605c..53d48c5 100644
--- a/src/websocket.c
+++ b/src/websocket.c
@@ -117,12 +117,14 @@ ws_handshake_reply(struct http_client *c) {
 
 	/* need those headers */
 	if(!origin || !origin_sz || !host || !host_sz || !c->path || !c->path_sz) {
+		slog(c->s, WEBDIS_WARNING, "Missing headers for WS handshake", 0);
 		return -1;
 	}
 
 	memset(sha1_handshake, 0, sizeof(sha1_handshake));
 	if(ws_compute_handshake(c, &sha1_handshake[0], &handshake_sz) != 0) {
 		/* failed to compute handshake. */
+		slog(c->s, WEBDIS_WARNING, "Failed to compute handshake", 0);
 		return -1;
 	}
 

From 03ff07252ee058154c967afcb6854137c8a1990e Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 17:32:31 -0700
Subject: [PATCH 26/28] Clean up http_response object when write cannot be
 scheduled

If the client closes the connection before we can even start to respond,
the event_add will fail and we need to clean up the http_response object
since this would have happened only after we've sent the whole response.
---
 src/http.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/src/http.c b/src/http.c
index ef4ea9a..66f8135 100644
--- a/src/http.c
+++ b/src/http.c
@@ -2,6 +2,7 @@
 #include "server.h"
 #include "worker.h"
 #include "client.h"
+#include "slog.h"
 
 #include <string.h>
 #include <stdlib.h>
@@ -137,7 +138,11 @@ http_schedule_write(int fd, struct http_response *r) {
 	if(r->w) { /* async */
 		event_set(&r->ev, fd, EV_WRITE, http_can_write, r);
 		event_base_set(r->w->base, &r->ev);
-		event_add(&r->ev, NULL);
+		int ret = event_add(&r->ev, NULL);
+		if (ret != 0) { /* could not schedule write */
+			slog(r->w->s, WEBDIS_ERROR, "Could not schedule HTTP write", 0);
+			http_response_cleanup(r, fd, 0);
+		}
 	} else { /* blocking */
 		http_can_write(fd, 0, r);
 	}

From 69be409b872cbe9acb7a22954997ed590eb7e921 Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 17:53:49 -0700
Subject: [PATCH 27/28] PR review: unused code, comment style

---
 src/slog.c        | 2 +-
 src/worker.c      | 1 +
 tests/websocket.c | 3 +--
 3 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/slog.c b/src/slog.c
index cae6d9a..9bae415 100644
--- a/src/slog.c
+++ b/src/slog.c
@@ -130,7 +130,7 @@ slog_internal(struct server *s, log_level level,
 }
 
 /**
- * This wrapper around slog_internal that first checks the log level.
+ * Thin wrapper around slog_internal that first checks the log level.
  */
 void
 slog(struct server *s, log_level level,
diff --git a/src/worker.c b/src/worker.c
index 964d154..d5decef 100644
--- a/src/worker.c
+++ b/src/worker.c
@@ -35,6 +35,7 @@ worker_new(struct server *s) {
 
 void
 worker_can_read(int fd, short event, void *p) {
+
 	struct http_client *c = p;
 	int ret, nparsed;
 
diff --git a/tests/websocket.c b/tests/websocket.c
index 38f475e..cab2300 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -313,7 +313,6 @@ ws_on_header_field(http_parser *p, const char *at, size_t length) {
 	}
 	wt->debug("%s appended header name data: currently [%.*s]\n", __func__,
 		  (int)wt->cur_hdr_key_len, wt->cur_hdr_key);
-	// wt->cur_header_is_ws_resp = (strncasecmp(at, "Sec-WebSocket-Accept", 20) == 0) ? 1 : 0;
 
 	wt->hdr_last_cb_was_name = 1;
 	return 0;
@@ -419,7 +418,7 @@ ws_on_message_complete(http_parser *p) {
 	struct worker_thread *wt = p->data;
 
 	wt->debug("%s (wt=%p), upgrade=%d\n", __func__, wt, p->upgrade);
-	// we've received the full HTTP response now, so we're ready to send frames
+	/* we've received the full HTTP response now, so we're ready to send frames */
 	wt->state = WS_RECEIVED_HANDSHAKE;
 	ws_enqueue_frame(wt); /* add frame to buffer and register interest in writing */
 	return 0;

From 1204f66ec115403eadbdb4fe1fe96f843d13116f Mon Sep 17 00:00:00 2001
From: Jessie Murray <jessie.murray@protonmail.com>
Date: Sun, 18 Jul 2021 19:16:42 -0700
Subject: [PATCH 28/28] Add progress thread w/ custom interval for WS test

* Start progress thread that reports once a second by default
* Customizable rate with [--interval|-i]
* Portable semaphore tested on Linux & macOS
---
 tests/Makefile    |   2 +-
 tests/websocket.c | 160 ++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 134 insertions(+), 28 deletions(-)

diff --git a/tests/Makefile b/tests/Makefile
index b2fa1f3..55c87f5 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -1,7 +1,7 @@
 OUT=websocket pubsub
 OBJS=../src/http-parser/http_parser.o ../src/b64/cencode.o ../src/sha1/sha1.o
 CFLAGS=-Wall -Wextra -I../src -I../src/http-parser
-LDFLAGS=-levent -lpthread
+LDFLAGS=-levent -lpthread -lm
 
 # if `make` is run with DEBUG=1, include debug symbols (same as in Makefile in root directory)
 DEBUG_FLAGS=
diff --git a/tests/websocket.c b/tests/websocket.c
index cab2300..aa501ca 100644
--- a/tests/websocket.c
+++ b/tests/websocket.c
@@ -14,6 +14,13 @@
 #include <b64/cencode.h>
 #include <http-parser/http_parser.h>
 #include <sha1/sha1.h>
+#include <math.h>
+#include <locale.h>
+#ifdef __APPLE__
+#include <dispatch/dispatch.h>
+#else
+#include <semaphore.h>
+#endif
 
 #include <sys/types.h>
 #include <sys/socket.h>
@@ -30,7 +37,8 @@ enum worker_state {
 	WS_SENT_HANDSHAKE,
 	WS_RECEIVED_HANDSHAKE,
 	WS_SENT_FRAME,
-	WS_COMPLETE
+	WS_COMPLETE,
+	WS_BROKEN
 };
 
 enum mask_config {
@@ -87,6 +95,19 @@ struct worker_thread {
 	int (*debug)(const char *fmt, ...);
 };
 
+struct progress_thread {
+	pthread_t thread;
+#ifdef __APPLE__
+	dispatch_semaphore_t sem_finished;
+#else
+	sem_t sem_finished;
+#endif
+	struct worker_thread *workers;
+	int worker_count;
+	int msg_target;
+	float interval_sec;
+};
+
 int debug_noop(const char *fmt, ...) {
 	(void)fmt;
 	return 0;
@@ -142,9 +163,15 @@ wait_for_possible_write(struct worker_thread *wt);
 static void
 ws_enqueue_frame(struct worker_thread *wt);
 
+static void
+wt_mark_finished(struct worker_thread *wt, enum worker_state state) {
+	wt->state = state;
+	event_base_loopbreak(wt->base);
+}
+
 void
 process_message(struct worker_thread *wt, size_t sz) {
-	if (wt->msg_received && wt->msg_received % 1000 == 0) {
+	if (0 && wt->msg_received && wt->msg_received % 1000 == 0) {
 		printf("thread %d: %8d messages left (got %9d bytes so far).\n",
 		       wt->id,
 		       wt->msg_target - wt->msg_received, wt->byte_count);
@@ -156,7 +183,7 @@ process_message(struct worker_thread *wt, size_t sz) {
 	if (wt->msg_received == wt->msg_target) {
 		wt->debug("%s: thread %d has received all %d messages it expected\n",
 			  __func__, wt->id, wt->msg_received);
-		event_base_loopexit(wt->base, NULL);
+		wt_mark_finished(wt, WS_COMPLETE);
 	}
 }
 
@@ -218,7 +245,7 @@ websocket_can_read(int fd, short event, void *ptr) {
 	evbuffer_debug_dump(wt, wt->rbuffer);
 	if (ret == 0) {
 		wt->debug("We didn't read anything from the socket...\n");
-		event_base_loopexit(wt->base, NULL);
+		wt_mark_finished(wt, WS_BROKEN);
 		return;
 	}
 
@@ -238,7 +265,7 @@ websocket_can_read(int fd, short event, void *ptr) {
 
 			if (wt->state == WS_SENT_HANDSHAKE || /* haven't encountered end of response yet */
 			    (wt->parser.upgrade && nparsed != (int)avail_sz -1)) {
-				wt->debug("UPGRADE *and* we have some data left\n");
+				wt->debug("UPGRADE *and* we have some data left (nparsed=%d, avail_sz=%lu)\n", nparsed, avail_sz);
 				continue;
 			} else if (wt->state == WS_RECEIVED_HANDSHAKE) { /* we have the full response */
 				evbuffer_drain(wt->rbuffer, evbuffer_get_length(wt->rbuffer));
@@ -431,7 +458,75 @@ ws_on_timeout(evutil_socket_t fd, short event, void *arg) {
 	(void)event;
 
 	fprintf(stderr, "Time has run out! (thread %d)\n", wt->id);
-	event_base_loopbreak(wt->base); /* break out of event loop */
+	wt_mark_finished(wt, WS_BROKEN); /* break out of event loop */
+}
+
+void*
+progress_thread_main(void *ptr) {
+	struct progress_thread *pt = ptr;
+	struct timespec ts_wait;
+	ts_wait.tv_sec = floor(pt->interval_sec); /* integer seconds */
+	ts_wait.tv_nsec = (pt->interval_sec - (float)ts_wait.tv_sec) * 1e9; /* nanoseconds */
+
+	int last_received = 0;
+	int num_sleeps = 0;
+	setlocale(LC_NUMERIC, "");
+
+	struct timespec ts_start;
+	clock_gettime(CLOCK_MONOTONIC, &ts_start);
+
+	while(1) {
+		int sem_received = 0;
+#ifdef __APPLE__
+	dispatch_time_t sem_timeout = dispatch_time(DISPATCH_TIME_NOW, (int64_t)(ts_wait.tv_sec * NSEC_PER_SEC + ts_wait.tv_nsec));
+    if (dispatch_semaphore_wait(pt->sem_finished, sem_timeout) == 0) {
+		sem_received = 1;
+	}
+#else
+	struct timespec ts_now, ts_sem_timeout; /* now + timeout */
+
+	/* get current time */
+    if (clock_gettime(CLOCK_REALTIME, &ts_now) == -1) {
+		fprintf(stderr, "clock_gettime failed: %s\n", strerror(errno));
+        exit(EXIT_FAILURE);
+    }
+	/* calculate when the timeout should occur */
+	long long now_nanos = ts_now.tv_sec * 1e9 + ts_now.tv_nsec;
+	long long sem_timeout_nanos = now_nanos + (long long)ts_wait.tv_sec * 1e9 + (long long)ts_wait.tv_nsec;
+	ts_sem_timeout.tv_sec = sem_timeout_nanos / 1000000000LL;
+	ts_sem_timeout.tv_nsec = sem_timeout_nanos % 1000000000LL;
+
+	int sem_ret = sem_timedwait(&pt->sem_finished, &ts_sem_timeout);
+	if (sem_ret == 0) {
+		sem_received = 1;
+	}
+#endif
+		// nanosleep(&ts, NULL);
+		num_sleeps++;
+		int total_sent = 0, total_received = 0, any_broken = 0, num_complete = 0;
+		for (int i = 0; i < pt->worker_count; i++) {
+			total_sent += pt->workers[i].msg_sent;
+			total_received += pt->workers[i].msg_received;
+			if (pt->workers[i].state == WS_BROKEN) {
+				any_broken = 1;
+			} else if (pt->workers[i].state == WS_COMPLETE) {
+				num_complete++;
+			}
+		}
+		struct timespec ts_after_sleep;
+		clock_gettime(CLOCK_MONOTONIC, &ts_after_sleep);
+		fprintf(stderr, "After %0.2f sec: %'d messages sent, %'d received (%.02f%%). Instant rate: %'ld/sec, overall rate: %'ld/sec\n",
+			((float)((ts_after_sleep.tv_sec * 1e9 + ts_after_sleep.tv_nsec) - (ts_start.tv_sec * 1e9 + ts_start.tv_nsec))) / (float)1e9,
+			total_sent, total_received, 100.0f * (float)total_received / (float)(pt->worker_count * pt->msg_target),
+			lroundf((float)(total_received - last_received) / pt->interval_sec),
+			lroundf((float)total_received / ((float)num_sleeps) * pt->interval_sec));
+
+		if (sem_received || total_received == pt->msg_target * pt->worker_count || any_broken || num_complete == pt->worker_count) {
+			break;
+		}
+		last_received = total_received;
+	}
+	return NULL;
 }
 
 void*
@@ -560,6 +655,7 @@ void usage(const char *argv0, char *host_default, short port_default,
 	       "\t[--messages|-n] COUNT\t(number of messages per thread, default = %d)\n"
 	       "\t[--mask|-m] MASK_CFG\t(%d: always, %d: never, %d: alternate, default = always)\n"
 	       "\t[--max-time|-t] SECONDS\t(max time to give to the run, default = unlimited)\n"
+	       "\t[--interval|-i] SECONDS\t(interval at which to report progress, default = 1)\n"
 	       "\t[--verbose|-v]\t\t(extremely verbose output)\n",
 	       argv0, host_default, (int)port_default,
 	       thread_count_default, messages_default,
@@ -569,8 +665,6 @@ void usage(const char *argv0, char *host_default, short port_default,
 int
 main(int argc, char *argv[]) {
 
-	struct timespec t0, t1;
-
 	int messages_default = 2500;
 	int thread_count_default = 4;
 	short port_default = 7379;
@@ -583,6 +677,7 @@ main(int argc, char *argv[]) {
 	long total = 0, total_bytes = 0;
 	int verbose = 0;
 	int timeout_seconds = -1;
+	float report_interval = 1.0;
 	enum mask_config mask_cfg = MASK_ALWAYS;
 
 	struct host_info hi = {host_default, port_default};
@@ -598,9 +693,10 @@ main(int argc, char *argv[]) {
 	    {"messages", required_argument, NULL, 'n'},
 	    {"mask", required_argument, NULL, 'm'},
 	    {"max-time", required_argument, NULL, 't'},
+	    {"interval", required_argument, NULL, 'i'},
 	    {"verbose", no_argument, NULL, 'v'},
 	    {0, 0, 0, 0}};
-	while ((opt = getopt_long(argc, argv, "h:p:c:n:m:t:vs", long_options, NULL)) != -1) {
+	while ((opt = getopt_long(argc, argv, "h:p:c:n:m:t:i:vs", long_options, NULL)) != -1) {
 		switch (opt) {
 		case 'h':
 			colon = strchr(optarg, ':');
@@ -640,6 +736,10 @@ main(int argc, char *argv[]) {
 			timeout_seconds = atoi(optarg);
 			break;
 
+		case 'i':
+			report_interval = atof(optarg);
+			break;
+
 		case 'v':
 			verbose = 1;
 			break;
@@ -655,7 +755,22 @@ main(int argc, char *argv[]) {
 	/* run threads */
 	workers = calloc(sizeof(struct worker_thread), thread_count);
 
-	clock_gettime(CLOCK_MONOTONIC, &t0);
+	struct progress_thread progress;
+	progress.interval_sec = report_interval;
+	progress.msg_target = msg_target;
+	progress.worker_count = thread_count;
+	progress.workers = workers;
+#ifdef __APPLE__
+	dispatch_semaphore_t *sem = &progress.sem_finished;
+	*sem = dispatch_semaphore_create(0);
+#else
+    if (sem_init(&progress.sem_finished, 0, 0) != 0) {
+		fprintf(stderr, "sem_init failed: %s\n", strerror(errno));
+        exit(EXIT_FAILURE);
+    }
+#endif
+	pthread_create(&progress.thread, NULL, progress_thread_main, &progress);
+
 	for (i = 0; i < thread_count; ++i) {
 		workers[i].id = i;
 		workers[i].msg_target = msg_target;
@@ -676,25 +791,16 @@ main(int argc, char *argv[]) {
 		total_bytes += workers[i].byte_count;
 	}
 
-	/* timing */
-	clock_gettime(CLOCK_MONOTONIC, &t1);
-	float mili0 = t0.tv_sec * 1000 + t0.tv_nsec / 1000000;
-	float mili1 = t1.tv_sec * 1000 + t1.tv_nsec / 1000000;
+	/* signal progress thread to stop */
+#ifdef __APPLE__
+	dispatch_semaphore_signal(progress.sem_finished);
+#else
+	sem_post(&progress.sem_finished);
+#endif
 
-	if (total != 0) {
-		int total_masked = 0;
-		for (i = 0; i < thread_count; ++i) {
-			total_masked += workers[i].mask_applied;
-		}
+	pthread_join(progress.thread, NULL);
 
-		double kb_per_sec = ((double)total_bytes / (double)(mili1 - mili0)) / 1.024;
-		printf("Sent+received %ld messages (%d sent masked) for a total of %ld bytes in %0.2f sec: %0.2f msg/sec (%0.2f KB/sec)\n",
-		       total,
-		       total_masked,
-		       total_bytes,
-		       (mili1 - mili0) / 1000.0,
-		       1000 * ((double)total) / (mili1 - mili0),
-		       kb_per_sec);
+	if (total != 0) {
 		return (total == thread_count * msg_target ? EXIT_SUCCESS : EXIT_FAILURE);
 	} else {
 		printf("No message was read.\n");