lighttpd1.4/src/mod_accesslog.c

#define _GNU_SOURCE

#include <sys/types.h>
#include <sys/stat.h>

#include <ctype.h>
#include <stdlib.h>
#include <string.h>
#include <fcntl.h>
#include <unistd.h>
#include <errno.h>
#include <time.h>

#include <stdio.h>

#include "base.h"
#include "log.h"
#include "buffer.h"

#include "plugin.h"

#include "inet_ntop_cache.h"

#include "sys-socket.h"

#ifdef HAVE_SYSLOG_H
# include <syslog.h>
#endif

typedef struct {
	char key;
	enum {
		FORMAT_UNSET,
			FORMAT_UNSUPPORTED,
			FORMAT_PERCENT,
			FORMAT_REMOTE_HOST,
			FORMAT_REMOTE_IDENT,
			FORMAT_REMOTE_USER,
			FORMAT_TIMESTAMP,
			FORMAT_REQUEST_LINE,
			FORMAT_STATUS,
			FORMAT_BYTES_OUT_NO_HEADER,
			FORMAT_HEADER,

			FORMAT_REMOTE_ADDR,
			FORMAT_LOCAL_ADDR,
			FORMAT_COOKIE,
			FORMAT_TIME_USED_MS,
			FORMAT_ENV,
			FORMAT_FILENAME,
			FORMAT_REQUEST_PROTOCOL,
			FORMAT_REQUEST_METHOD,
			FORMAT_SERVER_PORT,
			FORMAT_QUERY_STRING,
			FORMAT_TIME_USED,
			FORMAT_URL,
			FORMAT_SERVER_NAME,
			FORMAT_HTTP_HOST,
			FORMAT_CONNECTION_STATUS,
			FORMAT_BYTES_IN,
			FORMAT_BYTES_OUT,

			FORMAT_RESPONSE_HEADER
	} type;
} format_mapping;

/**
 *
 *
 * "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""
 *
 */

const format_mapping fmap[] =
{
	{ '%', FORMAT_PERCENT },
	{ 'h', FORMAT_REMOTE_HOST },
	{ 'l', FORMAT_REMOTE_IDENT },
	{ 'u', FORMAT_REMOTE_USER },
	{ 't', FORMAT_TIMESTAMP },
	{ 'r', FORMAT_REQUEST_LINE },
	{ 's', FORMAT_STATUS },
	{ 'b', FORMAT_BYTES_OUT_NO_HEADER },
	{ 'i', FORMAT_HEADER },

	{ 'a', FORMAT_REMOTE_ADDR },
	{ 'A', FORMAT_LOCAL_ADDR },
	{ 'B', FORMAT_BYTES_OUT_NO_HEADER },
	{ 'C', FORMAT_COOKIE },
	{ 'D', FORMAT_TIME_USED_MS },
	{ 'e', FORMAT_ENV },
	{ 'f', FORMAT_FILENAME },
	{ 'H', FORMAT_REQUEST_PROTOCOL },
	{ 'm', FORMAT_REQUEST_METHOD },
	{ 'n', FORMAT_UNSUPPORTED }, /* we have no notes */
	{ 'p', FORMAT_SERVER_PORT },
	{ 'P', FORMAT_UNSUPPORTED }, /* we are only one process */
	{ 'q', FORMAT_QUERY_STRING },
	{ 'T', FORMAT_TIME_USED },
	{ 'U', FORMAT_URL }, /* w/o querystring */
	{ 'v', FORMAT_SERVER_NAME },
	{ 'V', FORMAT_HTTP_HOST },
	{ 'X', FORMAT_CONNECTION_STATUS },
	{ 'I', FORMAT_BYTES_IN },
	{ 'O', FORMAT_BYTES_OUT },

	{ 'o', FORMAT_RESPONSE_HEADER },

	{ '\0', FORMAT_UNSET }
};


typedef struct {
	enum { FIELD_UNSET, FIELD_STRING, FIELD_FORMAT } type;

	buffer *string;
	int field;
} format_field;

typedef struct {
	format_field **ptr;

	size_t used;
	size_t size;
} format_fields;

typedef struct {
	buffer *access_logfile;
	buffer *format;
	unsigned short use_syslog;


	int    log_access_fd;
	time_t last_generated_accesslog_ts;
	time_t *last_generated_accesslog_ts_ptr;


	buffer *access_logbuffer;
	buffer *ts_accesslog_str;

	format_fields *parsed_format;
} plugin_config;

typedef struct {
	PLUGIN_DATA;

	plugin_config **config_storage;
	plugin_config conf;
} plugin_data;

INIT_FUNC(mod_accesslog_init) {
	plugin_data *p;

	p = calloc(1, sizeof(*p));

	return p;
}

int accesslog_parse_format(server *srv, format_fields *fields, buffer *format) {
	size_t i, j, k = 0, start = 0;

	if (format->used == 0) return -1;

	for (i = 0; i < format->used - 1; i++) {
		switch(format->ptr[i]) {
		case '%':
			if (i > 0 && start != i) {
				/* copy the string before this % */
				if (fields->size == 0) {
					fields->size = 16;
					fields->used = 0;
					fields->ptr = malloc(fields->size * sizeof(format_fields * ));
				} else if (fields->used == fields->size) {
					fields->size += 16;
					fields->ptr = realloc(fields->ptr, fields->size * sizeof(format_fields * ));
				}

				fields->ptr[fields->used] = malloc(sizeof(format_fields));
				fields->ptr[fields->used]->type = FIELD_STRING;
				fields->ptr[fields->used]->string = buffer_init();

				buffer_copy_string_len(fields->ptr[fields->used]->string, format->ptr + start, i - start);

				fields->used++;
			}

			/* we need a new field */

			if (fields->size == 0) {
				fields->size = 16;
				fields->used = 0;
				fields->ptr = malloc(fields->size * sizeof(format_fields * ));
			} else if (fields->used == fields->size) {
				fields->size += 16;
				fields->ptr = realloc(fields->ptr, fields->size * sizeof(format_fields * ));
			}

			/* search for the terminating command */
			switch (format->ptr[i+1]) {
			case '>':
			case '<':
				/* after the } has to be a character */
				if (format->ptr[i+2] == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "%< and %> have to be followed by a format-specifier");
					return -1;
				}


				for (j = 0; fmap[j].key != '\0'; j++) {
					if (fmap[j].key != format->ptr[i+2]) continue;

					/* found key */

					fields->ptr[fields->used] = malloc(sizeof(format_fields));
					fields->ptr[fields->used]->type = FIELD_FORMAT;
					fields->ptr[fields->used]->field = fmap[j].type;
					fields->ptr[fields->used]->string = NULL;

					fields->used++;

					break;
				}

				if (fmap[j].key == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "%< and %> have to be followed by a valid format-specifier");
					return -1;
				}

				start = i + 3;
				i = start - 1; /* skip the string */

				break;
			case '{':
				/* go forward to } */

				for (k = i+2; k < format->used - 1; k++) {
					if (format->ptr[k] == '}') break;
				}

				if (k == format->used - 1) {
					log_error_write(srv, __FILE__, __LINE__, "s", "%{ has to be terminated by a }");
					return -1;
				}

				/* after the } has to be a character */
				if (format->ptr[k+1] == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "%{...} has to be followed by a format-specifier");
					return -1;
				}

				if (k == i + 2) {
					log_error_write(srv, __FILE__, __LINE__, "s", "%{...} has to be contain a string");
					return -1;
				}

				for (j = 0; fmap[j].key != '\0'; j++) {
					if (fmap[j].key != format->ptr[k+1]) continue;

					/* found key */

					fields->ptr[fields->used] = malloc(sizeof(format_fields));
					fields->ptr[fields->used]->type = FIELD_FORMAT;
					fields->ptr[fields->used]->field = fmap[j].type;
					fields->ptr[fields->used]->string = buffer_init();

					buffer_copy_string_len(fields->ptr[fields->used]->string, format->ptr + i + 2, k - (i + 2));

					fields->used++;

					break;
				}

				if (fmap[j].key == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "%{...} has to be followed by a valid format-specifier");
					return -1;
				}

				start = k + 2;
				i = start - 1; /* skip the string */

				break;
			default:
				/* after the % has to be a character */
				if (format->ptr[i+1] == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "% has to be followed by a format-specifier");
					return -1;
				}

				for (j = 0; fmap[j].key != '\0'; j++) {
					if (fmap[j].key != format->ptr[i+1]) continue;

					/* found key */

					fields->ptr[fields->used] = malloc(sizeof(format_fields));
					fields->ptr[fields->used]->type = FIELD_FORMAT;
					fields->ptr[fields->used]->field = fmap[j].type;
					fields->ptr[fields->used]->string = NULL;

					fields->used++;

					break;
				}

				if (fmap[j].key == '\0') {
					log_error_write(srv, __FILE__, __LINE__, "s", "% has to be followed by a valid format-specifier");
					return -1;
				}

				start = i + 2;
				i = start - 1; /* skip the string */

				break;
			}

			break;
		}
	}

	if (start < i) {
		/* copy the string */
		if (fields->size == 0) {
			fields->size = 16;
			fields->used = 0;
			fields->ptr = malloc(fields->size * sizeof(format_fields * ));
		} else if (fields->used == fields->size) {
			fields->size += 16;
			fields->ptr = realloc(fields->ptr, fields->size * sizeof(format_fields * ));
		}

		fields->ptr[fields->used] = malloc(sizeof(format_fields));
		fields->ptr[fields->used]->type = FIELD_STRING;
		fields->ptr[fields->used]->string = buffer_init();

		buffer_copy_string_len(fields->ptr[fields->used]->string, format->ptr + start, i - start);

		fields->used++;
	}

	return 0;
}

FREE_FUNC(mod_accesslog_free) {
	plugin_data *p = p_d;
	size_t i;

	if (!p) return HANDLER_GO_ON;

	if (p->config_storage) {

		for (i = 0; i < srv->config_context->used; i++) {
			plugin_config *s = p->config_storage[i];

			if (!s) continue;

			if (s->access_logbuffer->used) {
				if (s->use_syslog) {
# ifdef HAVE_SYSLOG_H
					if (s->access_logbuffer->used > 2) {
						syslog(LOG_INFO, "%*s", s->access_logbuffer->used - 2, s->access_logbuffer->ptr);
					}
# endif
				} else if (s->log_access_fd != -1) {
					write(s->log_access_fd, s->access_logbuffer->ptr, s->access_logbuffer->used - 1);
				}
			}

			if (s->log_access_fd != -1) close(s->log_access_fd);

			buffer_free(s->ts_accesslog_str);
			buffer_free(s->access_logbuffer);
			buffer_free(s->format);
			buffer_free(s->access_logfile);

			if (s->parsed_format) {
				size_t j;
				for (j = 0; j < s->parsed_format->used; j++) {
					if (s->parsed_format->ptr[j]->string) buffer_free(s->parsed_format->ptr[j]->string);
					free(s->parsed_format->ptr[j]);
				}
				free(s->parsed_format->ptr);
				free(s->parsed_format);
			}

			free(s);
		}

		free(p->config_storage);
	}

	free(p);

	return HANDLER_GO_ON;
}

SETDEFAULTS_FUNC(log_access_open) {
	plugin_data *p = p_d;
	size_t i = 0;

	config_values_t cv[] = {
		{ "accesslog.filename",             NULL, T_CONFIG_STRING, T_CONFIG_SCOPE_CONNECTION },
		{ "accesslog.use-syslog",           NULL, T_CONFIG_BOOLEAN, T_CONFIG_SCOPE_CONNECTION },
		{ "accesslog.format",               NULL, T_CONFIG_STRING, T_CONFIG_SCOPE_CONNECTION },
		{ NULL,                             NULL, T_CONFIG_UNSET, T_CONFIG_SCOPE_UNSET }
	};

	if (!p) return HANDLER_ERROR;

	p->config_storage = calloc(1, srv->config_context->used * sizeof(specific_config *));

	for (i = 0; i < srv->config_context->used; i++) {
		plugin_config *s;

		s = calloc(1, sizeof(plugin_config));
		s->access_logfile = buffer_init();
		s->format = buffer_init();
		s->access_logbuffer = buffer_init();
		s->ts_accesslog_str = buffer_init();
		s->log_access_fd = -1;
		s->last_generated_accesslog_ts = 0;
		s->last_generated_accesslog_ts_ptr = &(s->last_generated_accesslog_ts);


		cv[0].destination = s->access_logfile;
		cv[1].destination = &(s->use_syslog);
		cv[2].destination = s->format;

		p->config_storage[i] = s;

		if (0 != config_insert_values_global(srv, ((data_config *)srv->config_context->data[i])->value, cv)) {
			return HANDLER_ERROR;
		}

		if (i == 0 && buffer_is_empty(s->format)) {
			/* set a default logfile string */

			buffer_copy_string(s->format, "%h %V %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"");
		}

		/* parse */

		if (s->format->used) {
			s->parsed_format = calloc(1, sizeof(*(s->parsed_format)));

			if (-1 == accesslog_parse_format(srv, s->parsed_format, s->format)) {

				log_error_write(srv, __FILE__, __LINE__, "sb",
						"parsing accesslog-definition failed:", s->format);

				return HANDLER_ERROR;
			}
#if 0
			/* debugging */
			for (j = 0; j < s->parsed_format->used; j++) {
				switch (s->parsed_format->ptr[j]->type) {
				case FIELD_FORMAT:
					log_error_write(srv, __FILE__, __LINE__, "ssds",
							"config:", "format", s->parsed_format->ptr[j]->field,
							s->parsed_format->ptr[j]->string ?
							s->parsed_format->ptr[j]->string->ptr : "" );
					break;
				case FIELD_STRING:
					log_error_write(srv, __FILE__, __LINE__, "ssbs", "config:", "string '", s->parsed_format->ptr[j]->string, "'");
					break;
				default:
					break;
				}
			}
#endif
		}

		if (s->use_syslog) {
			/* ignore the next checks */
			continue;
		}

		if (s->access_logfile->used < 2) continue;

		if (s->access_logfile->ptr[0] == '|') {
#ifdef HAVE_FORK
			/* create write pipe and spawn process */

			int to_log_fds[2];
			pid_t pid;

			if (pipe(to_log_fds)) {
				log_error_write(srv, __FILE__, __LINE__, "ss", "pipe failed: ", strerror(errno));
				return HANDLER_ERROR;
			}

			/* fork, execve */
			switch (pid = fork()) {
			case 0:
				/* child */

				close(STDIN_FILENO);
				dup2(to_log_fds[0], STDIN_FILENO);
				close(to_log_fds[0]);
				/* not needed */
				close(to_log_fds[1]);

				openDevNull(STDERR_FILENO);

				/* we don't need the client socket */
				for (i = 3; i < 256; i++) {
					close(i);
				}

				/* exec the log-process (skip the | )
				 *
				 */

				execl("/bin/sh", "sh", "-c", s->access_logfile->ptr + 1, (char *)NULL);

				log_error_write(srv, __FILE__, __LINE__, "sss",
						"spawning log-process failed: ", strerror(errno),
						s->access_logfile->ptr + 1);

				exit(-1);
				break;
			case -1:
				/* error */
				log_error_write(srv, __FILE__, __LINE__, "ss", "fork failed: ", strerror(errno));
				break;
			default:
				close(to_log_fds[0]);

				s->log_access_fd = to_log_fds[1];

				break;
			}
#else
			return -1;
#endif
		} else if (-1 == (s->log_access_fd =
				  open(s->access_logfile->ptr, O_APPEND | O_WRONLY | O_CREAT | O_LARGEFILE, 0644))) {

			log_error_write(srv, __FILE__, __LINE__, "ssb",
					"opening access-log failed:",
					strerror(errno), s->access_logfile);

			return HANDLER_ERROR;
		}
		fcntl(s->log_access_fd, F_SETFD, FD_CLOEXEC);

	}

	return HANDLER_GO_ON;
}

SIGHUP_FUNC(log_access_cycle) {
	plugin_data *p = p_d;
	size_t i;

	if (!p->config_storage) return HANDLER_GO_ON;

	for (i = 0; i < srv->config_context->used; i++) {
		plugin_config *s = p->config_storage[i];

		if (s->access_logbuffer->used) {
			if (s->use_syslog) {
#ifdef HAVE_SYSLOG_H
				if (s->access_logbuffer->used > 2) {
					/* syslog appends a \n on its own */
					syslog(LOG_INFO, "%*s", s->access_logbuffer->used - 2, s->access_logbuffer->ptr);
				}
#endif
			} else if (s->log_access_fd != -1) {
				write(s->log_access_fd, s->access_logbuffer->ptr, s->access_logbuffer->used - 1);
			}

			buffer_reset(s->access_logbuffer);
		}

		if (s->use_syslog == 0 &&
		    s->access_logfile->used > 1 &&
		    s->access_logfile->ptr[0] != '|') {

			close(s->log_access_fd);

			if (-1 == (s->log_access_fd =
				   open(s->access_logfile->ptr, O_APPEND | O_WRONLY | O_CREAT | O_LARGEFILE, 0644))) {

				log_error_write(srv, __FILE__, __LINE__, "ss", "cycling access-log failed:", strerror(errno));

				return HANDLER_ERROR;
			}
		}
	}

	return HANDLER_GO_ON;
}

#define PATCH(x) \
	p->conf.x = s->x;
static int mod_accesslog_patch_connection(server *srv, connection *con, plugin_data *p) {
	size_t i, j;
	plugin_config *s = p->config_storage[0];

	PATCH(access_logfile);
	PATCH(format);
	PATCH(log_access_fd);
	PATCH(last_generated_accesslog_ts_ptr);
	PATCH(access_logbuffer);
	PATCH(ts_accesslog_str);
	PATCH(parsed_format);
	PATCH(use_syslog);

	/* skip the first, the global context */
	for (i = 1; i < srv->config_context->used; i++) {
		data_config *dc = (data_config *)srv->config_context->data[i];
		s = p->config_storage[i];

		/* condition didn't match */
		if (!config_check_cond(srv, con, dc)) continue;

		/* merge config */
		for (j = 0; j < dc->value->used; j++) {
			data_unset *du = dc->value->data[j];

			if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.filename"))) {
				PATCH(access_logfile);
				PATCH(log_access_fd);
				PATCH(last_generated_accesslog_ts_ptr);
				PATCH(access_logbuffer);
				PATCH(ts_accesslog_str);
			} else if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.format"))) {
				PATCH(format);
				PATCH(parsed_format);
			} else if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.use-syslog"))) {
				PATCH(use_syslog);
				PATCH(last_generated_accesslog_ts_ptr);
				PATCH(access_logbuffer);
				PATCH(ts_accesslog_str);
			}
		}
	}

	return 0;
}
#undef PATCH

REQUESTDONE_FUNC(log_access_write) {
	plugin_data *p = p_d;
	buffer *b;
	size_t j;

	int newts = 0;
	data_string *ds;

	mod_accesslog_patch_connection(srv, con, p);

	/* No output device, nothing to do */
	if (!p->conf.use_syslog && p->conf.log_access_fd == -1) return HANDLER_GO_ON;

	b = p->conf.access_logbuffer;
	if (b->used == 0) {
		buffer_copy_string(b, "");
	}

	for (j = 0; j < p->conf.parsed_format->used; j++) {
		switch(p->conf.parsed_format->ptr[j]->type) {
		case FIELD_STRING:
			buffer_append_string_buffer(b, p->conf.parsed_format->ptr[j]->string);
			break;
		case FIELD_FORMAT:
			switch(p->conf.parsed_format->ptr[j]->field) {
			case FORMAT_TIMESTAMP:

				/* cache the generated timestamp */
				if (srv->cur_ts != *(p->conf.last_generated_accesslog_ts_ptr)) {
					struct tm tm;
#if defined(HAVE_STRUCT_TM_GMTOFF)
					long scd, hrs, min;
#endif

					buffer_prepare_copy(p->conf.ts_accesslog_str, 255);
#if defined(HAVE_STRUCT_TM_GMTOFF)
# ifdef HAVE_LOCALTIME_R
					localtime_r(&(srv->cur_ts), &tm);
					strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, "[%d/%b/%Y:%H:%M:%S ", &tm);
# else
					strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, "[%d/%b/%Y:%H:%M:%S ", localtime(&(srv->cur_ts)));
# endif
					p->conf.ts_accesslog_str->used = strlen(p->conf.ts_accesslog_str->ptr) + 1;

					buffer_append_string(p->conf.ts_accesslog_str, tm.tm_gmtoff >= 0 ? "+" : "-");

					scd = abs(tm.tm_gmtoff);
					hrs = scd / 3600;
					min = (scd % 3600) / 60;

					/* hours */
					if (hrs < 10) buffer_append_string(p->conf.ts_accesslog_str, "0");
					buffer_append_long(p->conf.ts_accesslog_str, hrs);

					if (min < 10) buffer_append_string(p->conf.ts_accesslog_str, "0");
					buffer_append_long(p->conf.ts_accesslog_str, min);
					BUFFER_APPEND_STRING_CONST(p->conf.ts_accesslog_str, "]");
#else
#ifdef HAVE_GMTIME_R
					gmtime_r(&(srv->cur_ts), &tm);
					strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, "[%d/%b/%Y:%H:%M:%S +0000]", &tm);
#else
					strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, "[%d/%b/%Y:%H:%M:%S +0000]", gmtime(&(srv->cur_ts)));
#endif
					p->conf.ts_accesslog_str->used = strlen(p->conf.ts_accesslog_str->ptr) + 1;
#endif