accesslog: Added a filtering mode to collect such data as response codes.
[ashd.git] / src / accesslog.c
CommitLineData
048ac115
FT
1/*
2 ashd - A Sane HTTP Daemon
3 Copyright (C) 2008 Fredrik Tolf <fredrik@dolda2000.com>
4
5 This program is free software: you can redistribute it and/or modify
6 it under the terms of the GNU General Public License as published by
7 the Free Software Foundation, either version 3 of the License, or
8 (at your option) any later version.
9
10 This program is distributed in the hope that it will be useful,
11 but WITHOUT ANY WARRANTY; without even the implied warranty of
12 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13 GNU General Public License for more details.
14
15 You should have received a copy of the GNU General Public License
16 along with this program. If not, see <http://www.gnu.org/licenses/>.
17*/
18
19#include <stdlib.h>
20#include <stdio.h>
21#include <unistd.h>
22#include <string.h>
23#include <errno.h>
24#include <sys/poll.h>
25#include <time.h>
26#include <sys/time.h>
f99bcc64 27#include <signal.h>
472abd3c 28#include <fcntl.h>
5c805444 29#include <stdint.h>
ca170d77 30#include <sys/stat.h>
5c805444 31#include <sys/socket.h>
048ac115
FT
32
33#ifdef HAVE_CONFIG_H
34#include <config.h>
35#endif
36#include <utils.h>
37#include <log.h>
38#include <req.h>
39#include <proc.h>
5c805444
FT
40#include <mt.h>
41#include <mtio.h>
048ac115
FT
42
43#define DEFFORMAT "%{%Y-%m-%d %H:%M:%S}t %m %u %A \"%G\""
44
5c805444
FT
45static struct logdata {
46 struct hthead *req, *resp;
47 struct timeval start, end;
48 off_t bytesin, bytesout;
49} defdata = {
50 .bytesin = -1,
51 .bytesout = -1,
52};
53
54static int ch, filter;
f99bcc64 55static char *outname = NULL;
048ac115 56static FILE *out;
ca170d77 57static int flush = 1, locklog = 1;
048ac115 58static char *format;
f99bcc64 59static volatile int reopen = 0;
048ac115 60
39522714 61static void qputs(char *sp, FILE *o)
048ac115 62{
39522714
FT
63 unsigned char *s = (unsigned char *)sp;
64
048ac115
FT
65 for(; *s; s++) {
66 if(*s == '\"') {
67 fputs("\\\"", o);
68 } else if(*s == '\\') {
69 fputs("\\\\", o);
70 } else if(*s == '\n') {
71 fputs("\\n", o);
72 } else if(*s == '\t') {
73 fputs("\\t", o);
74 } else if((*s < 32) || (*s >= 128)) {
39522714 75 fprintf(o, "\\x%02x", (int)*s);
048ac115
FT
76 } else {
77 fputc(*s, o);
78 }
79 }
80}
81
5c805444 82static void logitem(struct logdata *data, char o, char *d)
048ac115
FT
83{
84 char *h, *p;
85 char buf[1024];
048ac115
FT
86
87 switch(o) {
88 case '%':
89 putc('%', out);
90 break;
91 case 'h':
5c805444 92 if((h = getheader(data->req, d)) == NULL) {
048ac115
FT
93 putc('-', out);
94 } else {
95 qputs(h, out);
96 }
97 break;
98 case 'u':
5c805444 99 qputs(data->req->url, out);
048ac115
FT
100 break;
101 case 'U':
5c805444
FT
102 strncpy(buf, data->req->url, sizeof(buf));
103 buf[sizeof(buf) - 1] = 0;
048ac115
FT
104 if((p = strchr(buf, '?')) != NULL)
105 *p = 0;
106 qputs(buf, out);
107 break;
108 case 'm':
5c805444 109 qputs(data->req->method, out);
048ac115
FT
110 break;
111 case 'r':
5c805444 112 qputs(data->req->rest, out);
048ac115
FT
113 break;
114 case 'v':
5c805444 115 qputs(data->req->ver, out);
048ac115
FT
116 break;
117 case 't':
118 if(!*d)
119 d = "%a, %d %b %Y %H:%M:%S %z";
5c805444 120 strftime(buf, sizeof(buf), d, localtime(&data->start.tv_sec));
048ac115
FT
121 qputs(buf, out);
122 break;
123 case 'T':
124 if(!*d)
125 d = "%a, %d %b %Y %H:%M:%S %z";
5c805444 126 strftime(buf, sizeof(buf), d, gmtime(&data->start.tv_sec));
048ac115
FT
127 qputs(buf, out);
128 break;
129 case 's':
5c805444
FT
130 fprintf(out, "%06i", (int)data->start.tv_usec);
131 break;
132 case 'c':
133 if(!data->resp)
134 putc('-', out);
135 else
136 fprintf(out, "%i", data->resp->code);
137 break;
138 case 'i':
139 if(data->bytesin < 0)
140 putc('-', out);
141 else
142 fprintf(out, "%ji", (intmax_t)data->bytesin);
143 break;
144 case 'o':
145 if(data->bytesout < 0)
146 putc('-', out);
147 else
148 fprintf(out, "%ji", (intmax_t)data->bytesout);
149 break;
150 case 'd':
151 if((data->end.tv_sec == 0) && (data->end.tv_usec == 0))
152 fputc('-', out);
153 else
154 fprintf(out, "%.6f", (data->end.tv_sec - data->start.tv_sec) + ((data->end.tv_usec - data->start.tv_usec) / 1000000.0));
048ac115
FT
155 break;
156 case 'A':
5c805444 157 logitem(data, 'h', "X-Ash-Address");
048ac115
FT
158 break;
159 case 'H':
5c805444 160 logitem(data, 'h', "Host");
048ac115
FT
161 break;
162 case 'R':
5c805444 163 logitem(data, 'h', "Referer");
048ac115
FT
164 break;
165 case 'G':
5c805444 166 logitem(data, 'h', "User-Agent");
048ac115
FT
167 break;
168 }
169}
170
5c805444 171static void logreq(struct logdata *data)
048ac115
FT
172{
173 char *p, *p2;
174 char d[strlen(format)];
175 char o;
176
177 p = format;
178 while(*p) {
179 if(*p == '%') {
180 p++;
181 if(*p == '{') {
182 p++;
183 if((p2 = strchr(p, '}')) == NULL)
184 continue;
185 memcpy(d, p, p2 - p);
186 d[p2 - p] = 0;
187 p = p2 + 1;
188 } else {
189 d[0] = 0;
190 }
191 o = *p++;
192 if(o == 0)
193 break;
5c805444 194 logitem(data, o, d);
048ac115
FT
195 } else {
196 fputc(*p++, out);
197 }
198 }
199 fputc('\n', out);
200 if(flush)
201 fflush(out);
202}
203
204static void serve(struct hthead *req, int fd)
205{
5c805444
FT
206 struct logdata data;
207
208 data = defdata;
209 data.req = req;
210 gettimeofday(&data.start, NULL);
048ac115
FT
211 if(sendreq(ch, req, fd)) {
212 flog(LOG_ERR, "accesslog: could not pass request to child: %s", strerror(errno));
213 exit(1);
214 }
5c805444
FT
215 logreq(&data);
216}
217
218static int passdata(FILE *in, FILE *out, off_t *passed)
219{
220 size_t read;
221 off_t total;
222 char buf[8192];
223
224 total = 0;
225 while(!feof(in)) {
226 read = fread(buf, 1, sizeof(buf), in);
227 if(ferror(in))
228 return(-1);
229 if(fwrite(buf, 1, read, out) != read)
230 return(-1);
231 total += read;
232 }
233 if(passed)
234 *passed = total;
235 return(0);
236}
237
238static void filterreq(struct muth *mt, va_list args)
239{
240 vavar(struct hthead *, req);
241 vavar(int, fd);
242 int pfds[2];
243 struct hthead *resp;
244 FILE *cl, *hd;
245 struct logdata data;
246
247 hd = NULL;
248 resp = NULL;
249 data = defdata;
250 data.req = req;
251 gettimeofday(&data.start, NULL);
252 cl = mtstdopen(fd, 1, 600, "r+");
253 if(socketpair(PF_UNIX, SOCK_STREAM, 0, pfds))
254 goto out;
255 hd = mtstdopen(pfds[1], 1, 600, "r+");
256 if(sendreq(ch, req, pfds[0])) {
257 close(pfds[0]);
258 goto out;
259 }
260 close(pfds[0]);
261
262 if(passdata(cl, hd, &data.bytesin))
263 goto out;
264 shutdown(pfds[1], SHUT_WR);
265 if((resp = parseresponse(hd)) == NULL)
266 goto out;
267 data.resp = resp;
268 writeresp(cl, resp);
269 fprintf(cl, "\r\n");
270 if(passdata(hd, cl, &data.bytesout))
271 goto out;
272 gettimeofday(&data.end, NULL);
273
274out:
275 logreq(&data);
276
277 freehthead(req);
278 if(resp != NULL)
279 freehthead(resp);
280 fclose(cl);
281 if(hd != NULL)
282 fclose(hd);
048ac115
FT
283}
284
f99bcc64
FT
285static void sighandler(int sig)
286{
5c805444
FT
287 if(sig == SIGHUP) {
288 if(filter)
289 exitioloop(2);
290 else
291 reopen = 1;
292 }
f99bcc64
FT
293}
294
ca170d77
FT
295static int lockfile(FILE *file)
296{
297 struct flock ld;
298
299 memset(&ld, 0, sizeof(ld));
300 ld.l_type = F_WRLCK;
301 ld.l_whence = SEEK_SET;
302 ld.l_start = 0;
303 ld.l_len = 0;
304 return(fcntl(fileno(file), F_SETLK, &ld));
305}
306
307static void fetchpid(char *filename)
308{
309 int fd, ret;
310 struct flock ld;
311
312 if((fd = open(filename, O_WRONLY)) < 0) {
313 fprintf(stderr, "accesslog: %s: %s\n", filename, strerror(errno));
314 exit(1);
315 }
316 memset(&ld, 0, sizeof(ld));
317 ld.l_type = F_WRLCK;
318 ld.l_whence = SEEK_SET;
319 ld.l_start = 0;
320 ld.l_len = 0;
321 ret = fcntl(fd, F_GETLK, &ld);
322 close(fd);
323 if(ret) {
324 fprintf(stderr, "accesslog: %s: %s\n", filename, strerror(errno));
325 exit(1);
326 }
327 if(ld.l_type == F_UNLCK) {
328 fprintf(stderr, "accesslog: %s: not locked\n", filename);
329 exit(1);
330 }
331 printf("%i\n", (int)ld.l_pid);
332}
333
f99bcc64
FT
334static void reopenlog(void)
335{
336 FILE *new;
ca170d77 337 struct stat olds, news;
f99bcc64
FT
338
339 if(outname == NULL) {
340 flog(LOG_WARNING, "accesslog: received SIGHUP but logging to stdout, so ignoring");
341 return;
342 }
ca170d77
FT
343 if(locklog) {
344 if(fstat(fileno(out), &olds)) {
345 flog(LOG_ERR, "accesslog: could not stat current logfile(?!): %s", strerror(errno));
346 return;
347 }
348 if(!stat(outname, &news)) {
349 if((olds.st_dev == news.st_dev) && (olds.st_ino == news.st_ino)) {
350 /*
351 * This needs to be ignored, because if the same logfile
352 * is opened and then closed, the lock is lost. To quote
353 * the Linux fcntl(2) manpage: "This is bad." No kidding.
354 *
355 * Technically, there is a race condition here when the
356 * file has been stat'ed but not yet opened, where the old
357 * log file, having been previously renamed, changes name
358 * back to the name accesslog knows and is thus reopened
359 * regardlessly, but I think that might fit under the
360 * idiom "pathological case". It should, at least, not be
361 * a security problem.
362 */
363 flog(LOG_INFO, "accesslog: received SIGHUP, but logfile has not changed, so ignoring");
364 return;
365 }
366 }
367 }
f99bcc64
FT
368 if((new = fopen(outname, "a")) == NULL) {
369 flog(LOG_WARNING, "accesslog: could not reopen log file `%s' on SIGHUP: %s", outname, strerror(errno));
370 return;
371 }
e09f3227 372 fcntl(fileno(new), F_SETFD, FD_CLOEXEC);
ca170d77
FT
373 if(locklog) {
374 if(lockfile(new)) {
375 if((errno == EAGAIN) || (errno == EACCES)) {
376 flog(LOG_ERR, "accesslog: logfile is already locked; reverting to current log", strerror(errno));
377 fclose(new);
378 return;
379 } else {
380 flog(LOG_WARNING, "accesslog: could not lock logfile, so no lock will be held: %s", strerror(errno));
381 }
382 }
383 }
f99bcc64
FT
384 fclose(out);
385 out = new;
386}
387
5c805444
FT
388static void listenloop(struct muth *mt, va_list args)
389{
390 vavar(int, lfd);
391 int fd;
392 struct hthead *req;
393
394 while(1) {
395 block(lfd, EV_READ, 0);
396 if((fd = recvreq(lfd, &req)) < 0) {
397 if(errno != 0)
398 flog(LOG_ERR, "accesslog: error in recvreq: %s", strerror(errno));
399 exit(1);
400 }
401 mustart(filterreq, req, fd);
402 }
403}
404
405static void chwatch(struct muth *mt, va_list args)
406{
407 vavar(int, cfd);
408
409 block(cfd, EV_READ, 0);
410 exitioloop(1);
411}
412
413static void floop(void)
414{
415 mustart(listenloop, 0);
416 mustart(chwatch, ch);
417 while(1) {
418 switch(ioloop()) {
419 case 0:
420 case 1:
421 return;
422 case 2:
423 reopenlog();
424 break;
425 }
426 }
427}
428
429static void sloop(void)
430{
431 int fd, ret;
432 struct hthead *req;
433 struct pollfd pfd[2];
434
435 while(1) {
436 if(reopen) {
437 reopenlog();
438 reopen = 0;
439 }
440 memset(pfd, 0, sizeof(pfd));
441 pfd[0].fd = 0;
442 pfd[0].events = POLLIN;
443 pfd[1].fd = ch;
444 pfd[1].events = POLLHUP;
445 if((ret = poll(pfd, 2, -1)) < 0) {
446 if(errno != EINTR) {
447 flog(LOG_ERR, "accesslog: error in poll: %s", strerror(errno));
448 exit(1);
449 }
450 }
451 if(pfd[0].revents) {
452 if((fd = recvreq(0, &req)) < 0) {
453 if(errno == 0)
454 return;
455 flog(LOG_ERR, "accesslog: error in recvreq: %s", strerror(errno));
456 exit(1);
457 }
458 serve(req, fd);
459 freehthead(req);
460 close(fd);
461 }
462 if(pfd[1].revents & POLLHUP)
463 return;
464 }
465}
466
048ac115
FT
467static void usage(FILE *out)
468{
ca170d77 469 fprintf(out, "usage: accesslog [-hFaL] [-f FORMAT] [-p PIDFILE] OUTFILE CHILD [ARGS...]\n");
e51483a1 470 fprintf(out, " accesslog -P LOGFILE\n");
048ac115
FT
471}
472
473int main(int argc, char **argv)
474{
5c805444 475 int c;
472abd3c
FT
476 char *pidfile;
477 FILE *pidout;
048ac115 478
472abd3c 479 pidfile = NULL;
5c805444 480 while((c = getopt(argc, argv, "+hFaeLf:p:P:")) >= 0) {
048ac115
FT
481 switch(c) {
482 case 'h':
483 usage(stdout);
484 exit(0);
048ac115
FT
485 case 'F':
486 flush = 0;
487 break;
ca170d77
FT
488 case 'L':
489 locklog = 0;
490 break;
5c805444
FT
491 case 'e':
492 filter = 1;
493 break;
048ac115
FT
494 case 'f':
495 format = optarg;
496 break;
ca170d77
FT
497 case 'P':
498 fetchpid(optarg);
499 exit(0);
472abd3c
FT
500 case 'p':
501 pidfile = optarg;
502 break;
048ac115 503 case 'a':
5c805444 504 format = "%A - - [%{%d/%b/%Y:%H:%M:%S %z}t] \"%m %u %v\" %c %o \"%R\" \"%G\"";
048ac115
FT
505 break;
506 default:
507 usage(stderr);
508 exit(1);
509 }
510 }
9701afc5 511 if(argc - optind < 2) {
048ac115
FT
512 usage(stderr);
513 exit(1);
514 }
515 if(format == NULL)
516 format = DEFFORMAT;
f99bcc64
FT
517 if(!strcmp(argv[optind], "-"))
518 outname = NULL;
519 else
520 outname = argv[optind];
521 if(outname == NULL) {
9701afc5 522 out = stdout;
e09f3227 523 locklog = 0;
9701afc5
FT
524 } else {
525 if((out = fopen(argv[optind], "a")) == NULL) {
526 flog(LOG_ERR, "accesslog: could not open %s for logging: %s", argv[optind], strerror(errno));
048ac115
FT
527 exit(1);
528 }
e09f3227 529 fcntl(fileno(out), F_SETFD, FD_CLOEXEC);
048ac115 530 }
ca170d77
FT
531 if(locklog) {
532 if(lockfile(out)) {
533 if((errno == EAGAIN) || (errno == EACCES)) {
534 flog(LOG_ERR, "accesslog: logfile is already locked", strerror(errno));
535 exit(1);
536 } else {
537 flog(LOG_WARNING, "accesslog: could not lock logfile: %s", strerror(errno));
538 }
539 }
540 }
9701afc5 541 if((ch = stdmkchild(argv + optind + 1, NULL, NULL)) < 0) {
e3f12675 542 flog(LOG_ERR, "accesslog: could not fork child: %s", strerror(errno));
048ac115
FT
543 exit(1);
544 }
f99bcc64 545 signal(SIGHUP, sighandler);
472abd3c
FT
546 if(pidfile) {
547 if(!strcmp(pidfile, "-")) {
548 if(!outname) {
549 flog(LOG_ERR, "accesslog: cannot derive PID file name without an output file");
550 exit(1);
551 }
552 pidfile = sprintf2("%s.pid", outname);
553 }
554 if((pidout = fopen(pidfile, "w")) == NULL) {
555 flog(LOG_ERR, "accesslog: could not open PID file %s for writing: %s", pidfile);
556 exit(1);
557 }
558 fprintf(pidout, "%i\n", (int)getpid());
559 fclose(pidout);
560 }
5c805444
FT
561 if(filter)
562 floop();
563 else
564 sloop();
f95bc205 565 fclose(out);
472abd3c
FT
566 if(pidfile != NULL)
567 unlink(pidfile);
048ac115
FT
568 return(0);
569}