Add access logging to Kore.

Makefile

@@ -4,7 +4,7 @@ CC=gcc
 BIN=kore
 
 S_SRC+=	src/kore.c src/buf.c src/config.c src/net.c src/spdy.c src/http.c \
-	src/module.c src/utils.c src/zlib_dict.c
+	src/accesslog.c src/module.c src/utils.c src/zlib_dict.c
 S_OBJS=	$(S_SRC:.c=.o)
 
 CFLAGS+=-I/usr/local/ssl/include

example.conf

@@ -30,7 +30,8 @@ load example/example.module
 # the directives that follow are to be applied upon.
 #
 # Additionally you can specify the following in a domain configuration:
-#	- Nothing yet
+#
+#	accesslog:	File where all requests are logged.
 #
 # Handlers
 #
@@ -42,10 +43,7 @@ load example/example.module
 
 # Example domain that responds to 10.211.55.33.
 domain 10.211.55.3
+accesslog	/var/log/kore_access.log
 static		/css/style.css		serve_style_css
 static		/			serve_index
 dynamic		^/[a-z0-9_]*$		serve_profile
-
-# Another domain that responds to foo.bar.
-#domain foo.bar
-#dynamic		^/*$			serve_foobar

includes/http.h

@@ -18,6 +18,8 @@
 #define __H_HTTP_H
 
 #define HTTP_HEADER_MAX_LEN	8192
+#define HTTP_URI_LEN		2000
+#define HTTP_USERAGENT_LEN	256
 #define HTTP_REQ_HEADER_MAX	25
 #define HTTP_MAX_QUERY_ARGS	10
 
@@ -44,8 +46,12 @@ struct http_arg {
 struct http_request {
 	u_int8_t		method;
 	u_int8_t		flags;
+	int			status;
+	u_int64_t		start;
+	u_int64_t		end;
 	char			*host;
 	char			*path;
+	char			*agent;
 	struct connection	*owner;
 	struct spdy_stream	*stream;
 	struct kore_buf		*post_data;
@@ -76,4 +82,6 @@ int		http_populate_arguments(struct http_request *);
 int		http_argument_lookup(struct http_request *,
 		    const char *, char **);
 
+void		kore_accesslog(struct http_request *);
+
 #endif /* !__H_HTTP_H */

includes/kore.h

@@ -24,6 +24,7 @@
 #define errno_s			strerror(errno)
 #define ssl_errno_s		ERR_error_string(ERR_get_error(), NULL)
 
+#define KORE_DOMAINNAME_LEN	254
 #define KORE_PIDFILE_DEFAULT	"/var/run/kore.pid"
 
 #define kore_debug(fmt, ...)	\
@@ -113,6 +114,13 @@ struct kore_worker {
 
 TAILQ_HEAD(kore_worker_h, kore_worker);
 
+struct module_domain {
+	char					*domain;
+	int					accesslog;
+	TAILQ_HEAD(, kore_module_handle)	handlers;
+	TAILQ_ENTRY(module_domain)		list;
+};
+
 #define KORE_BUF_INITIAL	128
 #define KORE_BUF_INCREMENT	KORE_BUF_INITIAL
 
@@ -142,21 +150,26 @@ extern u_int16_t		cpu_count;
 extern u_int8_t			worker_count;
 
 extern struct listener		server;
+extern struct kore_worker	*worker;
 extern struct kore_worker_h	kore_workers;
 
-void		kore_init(void);
 void		kore_worker_init(void);
 void		kore_worker_wait(int);
 void		kore_event_init(void);
 void		kore_event_wait(int);
+void		kore_platform_init(void);
+void		kore_accesslog_init(void);
+int		kore_accesslog_wait(void);
 void		kore_set_proctitle(char *);
 void		kore_worker_spawn(u_int16_t);
+void		kore_accesslog_worker_init(void);
 void		kore_worker_entry(struct kore_worker *);
 void		kore_worker_setcpu(struct kore_worker *);
 void		kore_event_schedule(int, int, int, void *);
 int		kore_connection_handle(struct connection *);
 int		kore_server_accept(struct listener *, struct connection **);
 
+u_int64_t	kore_time_ms(void);
 void		kore_log_init(void);
 void		*kore_malloc(size_t);
 void		*kore_calloc(size_t, size_t);
@@ -175,8 +188,10 @@ void		kore_module_load(char *);
 void		kore_module_reload(void);
 int		kore_module_loaded(void);
 int		kore_module_domain_new(char *);
+void		kore_module_domain_closelogs(void);
 void		*kore_module_handler_find(char *, char *);
 int		kore_module_handler_new(char *, char *, char *, int);
+struct module_domain	*kore_module_domain_lookup(char *);
 
 void		fatal(const char *, ...);
 void		kore_debug_internal(char *, int, const char *, ...);

src/accesslog.c

@@ -0,0 +1,162 @@
+/*
+ * Copyright (c) 2013 Joris Vink <joris@coders.se>
+ *
+ * Permission to use, copy, modify, and distribute this software for any
+ * purpose with or without fee is hereby granted, provided that the above
+ * copyright notice and this permission notice appear in all copies.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
+ * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+ * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
+ * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
+ * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
+ * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
+ * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ */
+
+#include <sys/param.h>
+#include <sys/types.h>
+#include <sys/socket.h>
+#include <sys/queue.h>
+
+#include <netinet/in.h>
+#include <arpa/inet.h>
+
+#include <openssl/err.h>
+#include <openssl/ssl.h>
+
+#include <errno.h>
+#include <fcntl.h>
+#include <poll.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <syslog.h>
+#include <regex.h>
+#include <zlib.h>
+
+#include "spdy.h"
+#include "kore.h"
+#include "http.h"
+
+static int		accesslog_fd[2];
+
+struct kore_log_packet {
+	u_int8_t	method;
+	int		status;
+	u_int16_t	time_req;
+	u_int16_t	worker_id;
+	u_int16_t	worker_cpu;
+	struct in_addr	src;
+	char		host[KORE_DOMAINNAME_LEN];
+	char		path[HTTP_URI_LEN];
+	char		agent[HTTP_USERAGENT_LEN];
+};
+
+void
+kore_accesslog_init(void)
+{
+	if (socketpair(AF_UNIX, SOCK_STREAM, 0, accesslog_fd) == -1)
+		fatal("kore_accesslog_init(): socketpair() %s", errno_s);
+}
+
+void
+kore_accesslog_worker_init(void)
+{
+	close(accesslog_fd[0]);
+	kore_module_domain_closelogs();
+}
+
+int
+kore_accesslog_wait(void)
+{
+	ssize_t			len;
+	time_t			now;
+	size_t			slen;
+	int			nfds;
+	struct module_domain	*dom;
+	struct pollfd		pfd[1];
+	struct kore_log_packet	logpacket;
+	char			*method, buf[4096], *tbuf;
+
+	pfd[0].fd = accesslog_fd[0];
+	pfd[0].events = POLLIN;
+	pfd[0].revents = 0;
+
+	nfds = poll(pfd, 1, 1000);
+	if (nfds == -1 || (pfd[0].revents & (POLLERR | POLLHUP | POLLNVAL))) {
+		if (nfds == -1 && errno == EINTR)
+			return (KORE_RESULT_OK);
+		kore_log(LOG_WARNING, "poll(): %s", errno_s);
+		return (KORE_RESULT_ERROR);
+	}
+
+	if (nfds == 0)
+		return (KORE_RESULT_OK);
+
+	len = recv(accesslog_fd[0], &logpacket, sizeof(logpacket), 0);
+	if (len == -1) {
+		kore_log(LOG_WARNING, "recv(): %s", errno_s);
+		return (KORE_RESULT_ERROR);
+	}
+
+	if (len != sizeof(logpacket))
+		return (KORE_RESULT_ERROR);
+
+	if ((dom = kore_module_domain_lookup(logpacket.host)) == NULL) {
+		kore_log(LOG_WARNING,
+		    "got accesslog packet for unknown domain: %s",
+		    logpacket.host);
+		return (KORE_RESULT_OK);
+	}
+
+	if (logpacket.method == HTTP_METHOD_GET)
+		method = "GET";
+	else
+		method = "POST";
+
+	time(&now);
+	tbuf = kore_time_to_date(now);
+	snprintf(buf, sizeof(buf), "[%s] %s %d %s %s (w#%d) (%dms) (%s)\n",
+	    tbuf, inet_ntoa(logpacket.src), logpacket.status, method,
+	    logpacket.path, logpacket.worker_id, logpacket.time_req,
+	    logpacket.agent);
+	slen = strlen(buf);
+
+	len = write(dom->accesslog, buf, slen);
+	if (len == -1) {
+		kore_log(LOG_WARNING,
+		    "kore_accesslog_wait(): write(): %s", errno_s);
+		return (KORE_RESULT_ERROR);
+	}
+
+	if ((size_t)len != slen)
+		kore_log(LOG_NOTICE, "accesslog: %s", buf);
+
+	return (KORE_RESULT_OK);
+}
+
+void
+kore_accesslog(struct http_request *req)
+{
+	ssize_t			len;
+	struct kore_log_packet	logpacket;
+
+	logpacket.status = req->status;
+	logpacket.method = req->method;
+	logpacket.worker_id = worker->id;
+	logpacket.worker_cpu = worker->cpu;
+	logpacket.src = req->owner->sin.sin_addr;
+	logpacket.time_req = req->end - req->start;
+	kore_strlcpy(logpacket.host, req->host, sizeof(logpacket.host));
+	kore_strlcpy(logpacket.path, req->path, sizeof(logpacket.path));
+	kore_strlcpy(logpacket.agent, req->agent, sizeof(logpacket.agent));
+
+	len = send(accesslog_fd[1], &logpacket, sizeof(logpacket), 0);
+	if (len == -1) {
+		kore_log(LOG_WARNING, "kore_accesslog(): send(): %s", errno_s);
+	} else if (len != sizeof(logpacket)) {
+		kore_log(LOG_WARNING, "short accesslog packet sent");
+	}
+}

src/bsd.c

@@ -51,7 +51,7 @@ static int			nchanges;
 static struct kevent		*changelist;
 
 void
-kore_init(void)
+kore_platform_init(void)
 {
 	cpu_count = 0;
 }

src/config.c

@@ -49,6 +49,7 @@ static int		configure_workers(char **);
 static int		configure_pidfile(char **);
 static int		configure_certfile(char **);
 static int		configure_certkey(char **);
+static int		configure_accesslog(char **);
 
 static struct {
 	const char		*name;
@@ -66,6 +67,7 @@ static struct {
 	{ "pidfile",		configure_pidfile },
 	{ "certfile",		configure_certfile },
 	{ "certkey",		configure_certkey },
+	{ "accesslog",		configure_accesslog },
 	{ NULL,			NULL },
 };
 
@@ -302,3 +304,35 @@ configure_certkey(char **argv)
 	return (KORE_RESULT_OK);
 }
 
+static int
+configure_accesslog(char **argv)
+{
+	struct module_domain	*dom;
+
+	if (argv[1] == NULL)
+		return (KORE_RESULT_ERROR);
+
+	if (current_domain == NULL) {
+		kore_debug("missing domain for accesslog");
+		return (KORE_RESULT_ERROR);
+	}
+
+	if ((dom = kore_module_domain_lookup(current_domain)) == NULL) {
+		kore_debug("current_domain not found: (%s)", current_domain);
+		return (KORE_RESULT_ERROR);
+	}
+
+	if (dom->accesslog != -1) {
+		kore_debug("domain %s already has an open accesslog",
+		    current_domain);
+		return (KORE_RESULT_ERROR);
+	}
+
+	dom->accesslog = open(argv[1], O_CREAT | O_APPEND | O_WRONLY, 0755);
+	if (dom->accesslog == -1) {
+		kore_debug("open(%s): %s", argv[1], errno_s);
+		return (KORE_RESULT_ERROR);
+	}
+
+	return (KORE_RESULT_OK);
+}

src/http.c

@@ -62,9 +62,17 @@ http_request_new(struct connection *c, struct spdy_stream *s, char *host,
 	kore_debug("http_request_new(%p, %p, %s, %s, %s)", c, s,
 	    host, method, path);
 
+	if (strlen(host) >= KORE_DOMAINNAME_LEN - 1)
+		return (KORE_RESULT_ERROR);
+	if (strlen(path) >= HTTP_URI_LEN - 1)
+		return (KORE_RESULT_ERROR);
+
 	req = (struct http_request *)kore_malloc(sizeof(*req));
+	req->end = 0;
+	req->start = 0;
 	req->flags = 0;
 	req->owner = c;
+	req->status = 0;
 	req->stream = s;
 	req->post_data = NULL;
 	req->host = kore_strdup(host);
@@ -84,6 +92,13 @@ http_request_new(struct connection *c, struct spdy_stream *s, char *host,
 		return (KORE_RESULT_ERROR);
 	}
 
+	if (s != NULL) {
+		if (!http_request_header_get(req, "user-agent", &(req->agent)))
+			req->agent = kore_strdup("unknown");
+	} else {
+		req->agent = NULL;
+	}
+
 	if (out != NULL)
 		*out = req;
 
@@ -112,10 +127,12 @@ http_process(void)
 			continue;
 
 		hdlr = kore_module_handler_find(req->host, req->path);
+		req->start = kore_time_ms();
 		if (hdlr == NULL)
 			r = http_generic_404(req);
 		else
 			r = hdlr(req);
+		req->end = kore_time_ms();
 
 		switch (r) {
 		case KORE_RESULT_OK:
@@ -131,6 +148,8 @@ http_process(void)
 		}
 
 		if (r != KORE_RESULT_RETRY) {
+			kore_accesslog(req);
+
 			TAILQ_REMOVE(&http_requests, req, list);
 			http_request_free(req);
 			http_request_count--;
@@ -187,6 +206,8 @@ http_request_free(struct http_request *req)
 
 	free(req->path);
 	free(req->host);
+	if (req->agent != NULL)
+		free(req->agent);
 	free(req);
 }
 
@@ -202,6 +223,7 @@ http_response(struct http_request *req, int status, u_int8_t *d, u_int32_t len)
 
 	kore_debug("http_response(%p, %d, %p, %d)", req, status, d, len);
 
+	req->status = status;
 	if (req->owner->proto == CONN_PROTO_SPDY) {
 		snprintf(sbuf, sizeof(sbuf), "%d", status);
 
@@ -368,10 +390,16 @@ http_header_recv(struct netbuf *nb)
 		}
 
 		*(p++) = '\0';
+		if (*p == ' ')
+			p++;
 		hdr = (struct http_header *)kore_malloc(sizeof(*hdr));
 		hdr->header = kore_strdup(headers[i]);
 		hdr->value = kore_strdup(p);
 		TAILQ_INSERT_TAIL(&(req->req_headers), hdr, list);
+
+		if (req->agent == NULL &&
+		    !strcasecmp(hdr->header, "user-agent"))
+			req->agent = kore_strdup(hdr->value);
 	}
 
 	free(hbuf);

src/kore.c

@@ -58,6 +58,7 @@ struct listener		server;
 pid_t			mypid = -1;
 u_int16_t		cpu_count = 1;
 struct kore_worker_h	kore_workers;
+struct kore_worker	*worker = NULL;
 int			kore_debug = 0;
 int			server_port = 0;
 u_int8_t		worker_count = 0;
@@ -91,9 +92,6 @@ main(int argc, char *argv[])
 	struct kore_worker	*kw, *next;
 	char			*config_file;
 
-	kore_log_init();
-	mypid = getpid();
-
 	if (getuid() != 0)
 		fatal("kore must be started as root");
 
@@ -118,6 +116,7 @@ main(int argc, char *argv[])
 	if (config_file == NULL)
 		fatal("please specify a configuration file to use (-c)");
 
+	mypid = getpid();
 	kore_parse_config(config_file);
 	if (!kore_module_loaded())
 		fatal("no site module was loaded");
@@ -133,7 +132,9 @@ main(int argc, char *argv[])
 	if (kore_certfile == NULL || kore_certkey == NULL)
 		fatal("missing certificate information");
 
-	kore_init();
+	kore_log_init();
+	kore_platform_init();
+	kore_accesslog_init();
 
 	if (!kore_server_sslstart())
 		fatal("cannot initiate SSL");
@@ -174,8 +175,9 @@ main(int argc, char *argv[])
 			sig_recv = 0;
 		}
 
+		if (!kore_accesslog_wait())
+			break;
 		kore_worker_wait(0);
-		sleep(1);
 	}
 
 	for (kw = TAILQ_FIRST(&kore_workers); kw != NULL; kw = next) {
@@ -354,6 +356,8 @@ kore_worker_entry(struct kore_worker *kw)
 	struct connection	*c, *cnext;
 	struct kore_worker	*k, *next;
 
+	worker = kw;
+
 	if (chroot(chroot_path) == -1)
 		fatal("cannot chroot(): %s", errno_s);
 	if (chdir("/") == -1)
@@ -385,9 +389,9 @@ kore_worker_entry(struct kore_worker *kw)
 
 	quit = 0;
 	kore_event_init();
+	kore_accesslog_worker_init();
 
-	kore_log(LOG_NOTICE, "worker %d going to work (CPU: %d)",
-	    kw->id, kw->cpu);
+	kore_log(LOG_NOTICE, "worker %d started (cpu#%d)", kw->id, kw->cpu);
 	for (;;) {
 		if (sig_recv != 0) {
 			if (sig_recv == SIGHUP)

src/linux.c

@@ -52,7 +52,7 @@ static int			efd = -1;
 static struct epoll_event	*events = NULL;
 
 void
-kore_init(void)
+kore_platform_init(void)
 {
 	if ((cpu_count = sysconf(_SC_NPROCESSORS_ONLN)) == -1) {
 		kore_debug("could not get number of cpu's falling back to 1");

src/module.c

@@ -46,14 +46,7 @@ static char		*mod_name = NULL;
 static time_t		mod_last_mtime = 0;
 char			*kore_module_onload = NULL;
 
-struct module_domain {
-	char					*domain;
-	TAILQ_HEAD(, kore_module_handle)	handlers;
-	TAILQ_ENTRY(module_domain)		list;
-};
-
 static TAILQ_HEAD(, module_domain)	domains;
-static struct module_domain		*kore_module_domain_lookup(char *);
 
 void
 kore_module_load(char *module_name)
@@ -132,6 +125,7 @@ kore_module_domain_new(char *domain)
 		return (KORE_RESULT_ERROR);
 
 	dom = (struct module_domain *)kore_malloc(sizeof(*dom));
+	dom->accesslog = -1;
 	dom->domain = kore_strdup(domain);
 	TAILQ_INIT(&(dom->handlers));
 	TAILQ_INSERT_TAIL(&domains, dom, list);
@@ -200,7 +194,7 @@ kore_module_handler_find(char *domain, char *path)
 	return (NULL);
 }
 
-static struct module_domain *
+struct module_domain *
 kore_module_domain_lookup(char *domain)
 {
 	struct module_domain	*dom;
@@ -212,3 +206,12 @@ kore_module_domain_lookup(char *domain)
 
 	return (NULL);
 }
+
+void
+kore_module_domain_closelogs(void)
+{
+	struct module_domain	*dom;
+
+	TAILQ_FOREACH(dom, &domains, list)
+		close(dom->accesslog);
+}

src/utils.c

@@ -18,6 +18,7 @@
 #include <sys/types.h>
 #include <sys/socket.h>
 #include <sys/queue.h>
+#include <sys/time.h>
 
 #include <netinet/in.h>
 #include <arpa/inet.h>
@@ -132,7 +133,10 @@ kore_log(int prio, const char *fmt, ...)
 	vsnprintf(buf, sizeof(buf), fmt, args);
 	va_end(args);
 
-	syslog(prio, "%s", buf);
+	if (worker != NULL)
+		syslog(prio, "[wrk %d]: %s", worker->id, buf);
+	else
+		syslog(prio, "[parent]: %s", buf);
 }
 
 void
@@ -298,6 +302,17 @@ kore_time_to_date(time_t now)
 	return (tbuf);
 }
 
+u_int64_t
+kore_time_ms(void)
+{
+	struct timeval		tv;
+
+	if (gettimeofday(&tv, NULL) == -1)
+		return (0);
+
+	return (tv.tv_sec * 1000 + (tv.tv_usec / 100));
+}
+
 void
 fatal(const char *fmt, ...)
 {