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