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