Add raw logging

src/CMakeLists.txt

@@ -46,6 +46,8 @@ ADD_EXECUTABLE(fcgi-debug
 	fcgi-debug.c
 	connection.c
 	tools.c
+	stream.c
+	log.c
 )
 
 ADD_TARGET_PROPERTIES(fcgi-debug LINK_FLAGS ${EV_LDFLAGS})

src/connection.c

@@ -1,18 +1,7 @@
 #include "fcgi-debug.h"
 
 static void connection_close(connection *con) {
-	ev_io_stop(con->srv->loop, &con->w_server);
-	ev_io_stop(con->srv->loop, &con->w_client);
-	if (-1 != con->fd_server) {
-		shutdown(con->fd_server, SHUT_RDWR);
-		close(con->fd_server);
-	}
-	if (-1 != con->fd_client) {
-		shutdown(con->fd_client, SHUT_RDWR);
-		close(con->fd_client);
-	}
-	g_string_free(con->send_client_buf, TRUE);
-	g_string_free(con->send_server_buf, TRUE);
+	stream_close(con->srv, &con->s_server, &con->s_client);
 	g_slice_free(connection, con);
 }
 
@@ -20,23 +9,26 @@ static gboolean connection_connect(connection *con) {
 	server *srv = con->srv;
 	if (con->client_connected) return TRUE;
 	ev_io_start(srv->loop, &srv->w_accept);
-	if (-1 == connect(con->fd_client, srv->client.saddr, srv->client.addr_len)) {
+	if (-1 == connect(con->s_client.fd, srv->client.saddr, srv->client.addr_len)) {
 		switch (errno) {
 		case EALREADY:
+#if EWOULDBLOCK != EAGAIN
+		case EWOULDBLOCK:
+#endif
 		case EINPROGRESS:
 		case EINTR:
 			ev_io_stop(srv->loop, &srv->w_accept); /* no new connections until we have a new connection to the client */
-			ev_io_set_events(srv->loop, &con->w_client, EV_WRITE | EV_READ);
+			ev_io_set_events(srv->loop, &con->s_client.watcher, EV_WRITE | EV_READ);
 			break;
 		default:
-			g_warning("couldn't connect: %s", g_strerror(errno));
+			g_warning("couldn't connect (%u): %s", con->con_id, g_strerror(errno));
 			connection_close(con);
 		}
 		return FALSE;
 	} else {
 		con->client_connected = TRUE;
-		ev_io_set_events(srv->loop, &con->w_client, EV_READ);
-		ev_io_set_events(srv->loop, &con->w_server, EV_READ);
+		stream_start(srv, &con->s_server);
+		stream_start(srv, &con->s_client);
 		return TRUE;
 	}
 }
@@ -46,103 +38,51 @@ static char readbuf[4096];
 static void fd_server_cb(struct ev_loop *loop, struct ev_io *w, int revents) {
 	connection *con = (connection*) w->data;
 	server *srv = con->srv;
+	GString s;
 	UNUSED(loop);
 
 	if (revents & EV_READ) {
-		int l = read(w->fd, readbuf, sizeof(readbuf));
-		switch (l) {
-		case -1:
-			switch (errno) {
-			case EAGAIN:
-			case EINTR:
-				break;
-			default:
-				g_warning("couldn't read from server: %s", g_strerror(errno));
-				connection_close(con);
-			}
-			return;
-		case 0:
-			/* end of file */
+		gssize len = stream_read(srv, &con->s_server, readbuf, sizeof(readbuf));
+		if (len == -1) {
+			g_print("connection closed (%u)\n", con->con_id);
 			connection_close(con);
 			return;
-		default:
-			break;
 		}
-		g_string_append_len(con->send_client_buf, readbuf, l);
-		if (con->send_client_buf->len > 4*4096) ev_io_rem_events(srv->loop, w, EV_READ);
-		ev_io_add_events(srv->loop, &con->w_client, EV_WRITE);
+		log_raw("raw from server", con->con_id, g_string_set_const(&s, readbuf, len));
+		stream_append(srv, &con->s_client, readbuf, len);
 	}
 	if (revents & EV_WRITE) {
-		if (con->send_server_buf->len > 0) {
-			int l = write(w->fd, con->send_server_buf->str, con->send_server_buf->len);
-			switch (l) {
-			case -1:
-				switch (errno) {
-				case EAGAIN:
-				case EINTR:
-					break;
-				default:
-					g_warning("couldn't write to server: %s", g_strerror(errno));
-					connection_close(con);
-				}
-				return;
-			}
-			g_string_erase(con->send_server_buf, 0, l);
-			if (con->send_server_buf->len < 4*4096) ev_io_add_events(srv->loop, &con->w_server, EV_READ);
+		if (-1 == stream_write(srv, &con->s_server)) {
+			g_print("connection closed (%u)\n", con->con_id);
+			connection_close(con);
+			return;
 		}
-		if (con->send_server_buf->len == 0) ev_io_rem_events(srv->loop, w, EV_WRITE);
 	}
 }
 
 static void fd_client_cb(struct ev_loop *loop, struct ev_io *w, int revents) {
 	connection *con = (connection*) w->data;
 	server *srv = con->srv;
+	GString s;
 	UNUSED(loop);
 	if (!connection_connect(con)) return;
 
 	if (revents & EV_READ) {
-		int l = read(w->fd, readbuf, sizeof(readbuf));
-		switch (l) {
-		case -1:
-			switch (errno) {
-			case EAGAIN:
-			case EINTR:
-				break;
-			default:
-				g_warning("couldn't read from client: %s", g_strerror(errno));
-				connection_close(con);
-			}
-			return;
-		case 0:
-			/* end of file */
+		gssize len = stream_read(srv, &con->s_client, readbuf, sizeof(readbuf));
+		if (len == -1) {
+			g_print("connection closed (%u)\n", con->con_id);
 			connection_close(con);
 			return;
-		default:
-			break;
 		}
-		g_string_append_len(con->send_server_buf, readbuf, l);
-		if (con->send_server_buf->len > 4*4096) ev_io_rem_events(srv->loop, w, EV_READ);
-		ev_io_add_events(srv->loop, &con->w_server, EV_WRITE);
+		log_raw("raw from client", con->con_id, g_string_set_const(&s, readbuf, len));
+		stream_append(srv, &con->s_server, readbuf, len);
 	}
 	if (revents & EV_WRITE) {
-		if (con->send_client_buf->len > 0) {
-			int l = write(w->fd, con->send_client_buf->str, con->send_client_buf->len);
-			switch (l) {
-			case -1:
-				switch (errno) {
-				case EAGAIN:
-				case EINTR:
-					break;
-				default:
-					g_warning("couldn't write to client: %s", g_strerror(errno));
-					connection_close(con);
-				}
-				return;
-			}
-			g_string_erase(con->send_client_buf, 0, l);
-			if (con->send_client_buf->len < 4*4096) ev_io_add_events(srv->loop, &con->w_client, EV_READ);
+		if (-1 == stream_write(srv, &con->s_client)) {
+			g_print("connection closed (%u)\n", con->con_id);
+			connection_close(con);
+			return;
 		}
-		if (con->send_client_buf->len == 0) ev_io_rem_events(srv->loop, w, EV_WRITE);
 	}
 }
 
@@ -151,24 +91,18 @@ void connection_new(server *srv, int fd_server) {
 	int fd_client;
 
 	fd_init(fd_server);
-	con = g_slice_new0(connection);
-	con->srv = srv;
-	con->fd_server = fd_server;
-	con->fd_client = -1;
-	ev_io_init(&con->w_server, fd_server_cb, fd_server, 0);
-	con->w_server.data = con;
-	ev_io_init(&con->w_client, fd_client_cb, -1, 0);
-	con->w_client.data = con;
-	con->send_client_buf = g_string_sized_new(0);
-	con->send_server_buf = g_string_sized_new(0);
 
 	if (-1 == (fd_client = socket(AF_UNIX, SOCK_STREAM, 0))) {
 		g_warning("couldn't create socket: %s", g_strerror(errno));
-		connection_close(con);
+		shutdown(fd_server, SHUT_RDWR);
+		close(fd_server);
+		return;
 	}
-	fd_init(fd_client);
-	con->fd_client = fd_client;
-	ev_io_set(&con->w_client, fd_client, EV_WRITE | EV_READ);
+	con = g_slice_new0(connection);
+	con->srv = srv;
+	con->con_id = srv->next_con_id++;
 	con->client_connected = FALSE;
+	g_print("new connection (%u)\n", con->con_id);
+	stream_init(srv, &con->s_server, &con->s_client, fd_server, fd_client, fd_server_cb, fd_client_cb, con);
 	connection_connect(con);
 }

src/fcgi-debug.h

@@ -13,12 +13,17 @@
 
 #define UNUSED(x) ( (void)(x) )
 
+#define MAX_STREAM_BUF_SIZE (128*1024)
+
 struct addr;
 typedef struct addr addr;
 
 struct server;
 typedef struct server server;
 
+struct stream;
+typedef struct stream stream;
+
 struct connection;
 typedef struct connection connection;
 
@@ -30,6 +35,8 @@ struct addr {
 struct server {
 	struct ev_loop *loop;
 
+	guint next_con_id;
+
 	ev_signal
 		sig_w_INT,
 		sig_w_TERM,
@@ -47,13 +54,18 @@ struct server {
 	gboolean exiting, stopped_signals;
 };
 
+struct stream {
+	stream *other;
+	int fd;
+	ev_io watcher;
+	GString *buffer;
+};
+
 struct connection {
 	server *srv;
-	int fd_server, fd_client;
-	ev_io w_server, w_client;
+	guint con_id;
+	stream s_server, s_client;
 	gboolean client_connected;
-
-	GString *send_client_buf, *send_server_buf;
 };
 
 
@@ -66,5 +78,22 @@ void ev_io_add_events(struct ev_loop *loop, ev_io *watcher, int events);
 void ev_io_rem_events(struct ev_loop *loop, ev_io *watcher, int events);
 void ev_io_set_events(struct ev_loop *loop, ev_io *watcher, int events);
 
+GString* g_string_set_const(GString* s, const gchar *data, gsize len);
+
 /* connection.c */
 void connection_new(server *srv, int fd_server);
+
+/* stream.c */
+typedef void (*ev_io_cb)(struct ev_loop *loop, ev_io *w, int revents);
+
+void stream_init(server *srv, stream *s1, stream *s2, int fd1, int fd2, ev_io_cb cb1, ev_io_cb cb2, void* data);
+void stream_close(server *srv, stream *s1, stream *s2);
+void stream_clean(server *srv, stream *s1, stream *s2);
+void stream_start(server *srv, stream *s);
+
+gssize stream_read(server *srv, stream *s, char *buf, gssize bufsize);
+void stream_append(server *srv, stream *s, char *buf, gssize bufsize);
+gssize stream_write(server *srv, stream *s);
+
+/* log.c */
+void log_raw(const gchar *head, guint con_id, GString *data);

src/log.c

@@ -0,0 +1,37 @@
+#include "fcgi-debug.h"
+
+void log_raw(const gchar *head, guint con_id, GString *data) {
+	const gchar *start = data->str, *end = start+data->len, *i;
+	GString *line = g_string_sized_new(0);
+	for ( ; start < end; ) {
+		i = start;
+		g_string_truncate(line, 0);
+		for ( ; i < end; i++) {
+			guchar c = *i;
+			if (c == '\n') {
+				g_string_append_len(line, "\\n", 2);
+				i++;
+				break;
+			} else if (c == '\r') {
+				g_string_append_len(line, "\\r", 2);
+				if (i + 1 < end && i[1] == '\n') {
+					i++;
+					g_string_append_len(line, "\\n", 2);
+				}
+				i++;
+				break;
+			} else if (c < 0x20 || c >= 0x80) {
+				static char hex[5] = "\\x00";
+				hex[3] = ((c & 0xF) < 10) ? '0' + (c & 0xF) : 'A' + (c & 0xF) - 10;
+				c /= 16;
+				hex[2] = ((c & 0xF) < 10) ? '0' + (c & 0xF) : 'A' + (c & 0xF) - 10;
+				g_string_append_len(line, hex, 4);
+			} else {
+				g_string_append_c(line, c);
+			}
+		}
+		g_print("%s (%u): %s\n", head, con_id, line->str);
+		start = i;
+	}
+	g_string_free(line, TRUE);
+}

src/stream.c

@@ -0,0 +1,105 @@
+#include "fcgi-debug.h"
+
+void stream_init(server *srv, stream *s1, stream *s2, int fd1, int fd2, ev_io_cb cb1, ev_io_cb cb2, void* data) {
+	UNUSED(srv);
+	fd_init(fd1);
+	fd_init(fd2);
+	s1->other = s2;
+	s2->other = s1;
+	s1->fd = fd1;
+	s2->fd = fd2;
+	ev_io_init(&s1->watcher, cb1, fd1, 0);
+	ev_io_init(&s2->watcher, cb2, fd2, 0);
+	s1->watcher.data = data;
+	s2->watcher.data = data;
+	s1->buffer = g_string_sized_new(0);
+	s2->buffer = g_string_sized_new(0);
+}
+
+void stream_close(server *srv, stream *s1, stream *s2) {
+	ev_io_stop(srv->loop, &s1->watcher);
+	if (s1->fd != -1) {
+		shutdown(s1->fd, SHUT_RDWR);
+		close(s1->fd);
+		s1->fd = -1;
+	}
+	ev_io_stop(srv->loop, &s2->watcher);
+	if (s2->fd != -1) {
+		shutdown(s2->fd, SHUT_RDWR);
+		close(s2->fd);
+		s2->fd = -1;
+	}
+}
+
+void stream_clean(server *srv, stream *s1, stream *s2) {
+	stream_close(srv, s1, s2);
+	if (s1->buffer) { g_string_free(s1->buffer, TRUE); s1->buffer = NULL; }
+	if (s2->buffer) { g_string_free(s2->buffer, TRUE); s2->buffer = NULL; }
+}
+
+void stream_start(server *srv, stream *s) {
+	int events = EV_READ;
+	if (s->buffer->len > 0) events |= EV_WRITE;
+	ev_io_add_events(srv->loop, &s->watcher, events);
+}
+
+/* -1: connection got closed, 0: nothing to read, n: read n bytes */
+gssize stream_read(server *srv, stream *s, char *buf, gssize bufsize) {
+	gssize len;
+	while (-1 == (len = read(s->fd, buf, bufsize))) {
+		switch (errno) {
+		case EAGAIN:
+#if EWOULDBLOCK != EAGAIN
+		case EWOULDBLOCK:
+#endif
+			/* nothing to read */
+			return 0;
+		case ECONNRESET:
+			stream_close(srv, s, s->other);
+			return -1;
+		case EINTR: /* try again */
+			break;
+		default:
+			g_message("read error: %s", g_strerror(errno));
+			stream_close(srv, s, s->other);
+			return -1;
+		}
+	}
+	if (0 == len) { /* connection closed */
+		stream_close(srv, s, s->other);
+		return -1;
+	}
+	return len;
+}
+
+void stream_append(server *srv, stream *s, char *buf, gssize bufsize) {
+	g_string_append_len(s->buffer, buf, bufsize);
+	if (s->buffer->len > 0) ev_io_add_events(srv->loop, &s->watcher, EV_WRITE);
+	if (s->buffer->len > MAX_STREAM_BUF_SIZE) ev_io_rem_events(srv->loop, &s->other->watcher, EV_READ);
+}
+
+/* -1: connection closed, n: wrote n bytes */
+gssize stream_write(server *srv, stream *s) {
+	gssize len;
+	while (-1 == (len = write(s->fd, s->buffer->str, s->buffer->len))) {
+		switch (errno) {
+		case EAGAIN:
+#if EWOULDBLOCK != EAGAIN
+		case EWOULDBLOCK:
+#endif
+			/* try again later */
+			return 0;
+		case ECONNRESET:
+		case EPIPE:
+			stream_close(srv, s, s->other);
+			return -1;
+		case EINTR: /* try again */
+			break;
+		default:
+			g_message("read error: %s", g_strerror(errno));
+			stream_close(srv, s, s->other);
+			return -1;
+		}
+	}
+	return 0;
+}

src/tools.c

@@ -49,3 +49,9 @@ void ev_io_set_events(struct ev_loop *loop, ev_io *watcher, int events) {
 	ev_io_set(watcher, watcher->fd, (watcher->events & ~(EV_READ | EV_WRITE)) | events);
 	ev_io_start(loop, watcher);
 }
+
+GString* g_string_set_const(GString* s, const gchar *data, gsize len) {
+	s->str = (gchar*) data;
+	s->len = len;
+	return s;
+}