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