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 }