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 }