src/log/access_log.cc

   1 /*
   2  * Copyright (C) 1996-2017 The Squid Software Foundation and contributors
   3  *
   4  * Squid software is distributed under GPLv2+ license and includes
   5  * contributions from numerous individuals and organizations.
   6  * Please see the COPYING and CONTRIBUTORS files for details.
   7  */
   8
   9 /* DEBUG: section 46    Access Log */
  10
  11 #include "squid.h"
  12 #include "AccessLogEntry.h"
  13 #include "acl/Checklist.h"
  14 #if USE_ADAPTATION
  15 #include "adaptation/Config.h"
  16 #endif
  17 #include "CachePeer.h"
  18 #include "err_detail_type.h"
  19 #include "errorpage.h"
  20 #include "format/Token.h"
  21 #include "globals.h"
  22 #include "hier_code.h"
  23 #include "HttpReply.h"
  24 #include "HttpRequest.h"
  25 #include "log/access_log.h"
  26 #include "log/Config.h"
  27 #include "log/CustomLog.h"
  28 #include "log/File.h"
  29 #include "log/Formats.h"
  30 #include "MemBuf.h"
  31 #include "mgr/Registration.h"
  32 #include "rfc1738.h"
  33 #include "SquidConfig.h"
  34 #include "SquidTime.h"
  35 #include "Store.h"
  36
  37 #if USE_SQUID_EUI
  38 #include "eui/Eui48.h"
  39 #include "eui/Eui64.h"
  40 #endif
  41
  42 #if HEADERS_LOG
  43 static Logfile *headerslog = NULL;
  44 #endif
  45
  46 #if MULTICAST_MISS_STREAM
  47 static int mcast_miss_fd = -1;
  48
  49 static struct sockaddr_in mcast_miss_to;
  50 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
  51 #endif
  52
  53 #if USE_FORW_VIA_DB
  54
  55 typedef struct {
  56     hash_link hash;
  57     int n;
  58 } fvdb_entry;
  59 static hash_table *via_table = NULL;
  60 static hash_table *forw_table = NULL;
  61 static void fvdbInit();
  62 static void fvdbDumpTable(StoreEntry * e, hash_table * hash);
  63 static void fvdbCount(hash_table * hash, const char *key);
  64 static OBJH fvdbDumpVia;
  65 static OBJH fvdbDumpForw;
  66 static FREE fvdbFreeEntry;
  67 static void fvdbClear(void);
  68 static void fvdbRegisterWithCacheManager();
  69 #endif
  70
  71 int LogfileStatus = LOG_DISABLE;
  72
  73 void
  74 accessLogLogTo(CustomLog* log, AccessLogEntry::Pointer &al, ACLChecklist * checklist)
  75 {
  76
  77     if (al->url.isEmpty())
  78         al->url = Format::Dash;
  79
  80     if (!al->http.content_type || *al->http.content_type == '\0')
  81         al->http.content_type = dash_str;
  82
  83     if (al->hier.host[0] == '\0')
  84         xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
  85
  86     for (; log; log = log->next) {
  87         if (log->aclList && checklist && !checklist->fastCheck(log->aclList).allowed())
  88             continue;
  89
  90         // The special-case "none" type has no logfile object set
  91         if (log->type == Log::Format::CLF_NONE)
  92             return;
  93
  94         if (log->logfile) {
  95             logfileLineStart(log->logfile);
  96
  97             switch (log->type) {
  98
  99             case Log::Format::CLF_SQUID:
 100                 Log::Format::SquidNative(al, log->logfile);
 101                 break;
 102
 103             case Log::Format::CLF_COMBINED:
 104                 Log::Format::HttpdCombined(al, log->logfile);
 105                 break;
 106
 107             case Log::Format::CLF_COMMON:
 108                 Log::Format::HttpdCommon(al, log->logfile);
 109                 break;
 110
 111             case Log::Format::CLF_REFERER:
 112                 Log::Format::SquidReferer(al, log->logfile);
 113                 break;
 114
 115             case Log::Format::CLF_USERAGENT:
 116                 Log::Format::SquidUserAgent(al, log->logfile);
 117                 break;
 118
 119             case Log::Format::CLF_CUSTOM:
 120                 Log::Format::SquidCustom(al, log);
 121                 break;
 122
 123 #if ICAP_CLIENT
 124             case Log::Format::CLF_ICAP_SQUID:
 125                 Log::Format::SquidIcap(al, log->logfile);
 126                 break;
 127 #endif
 128
 129             default:
 130                 fatalf("Unknown log format %d\n", log->type);
 131                 break;
 132             }
 133
 134             logfileLineEnd(log->logfile);
 135         }
 136
 137         // NP:  WTF?  if _any_ log line has no checklist ignore the following ones?
 138         if (!checklist)
 139             break;
 140     }
 141 }
 142
 143 void
 144 accessLogLog(AccessLogEntry::Pointer &al, ACLChecklist * checklist)
 145 {
 146     if (LogfileStatus != LOG_ENABLE)
 147         return;
 148
 149     accessLogLogTo(Config.Log.accesslogs, al, checklist);
 150 #if MULTICAST_MISS_STREAM
 151
 152     if (al->cache.code != LOG_TCP_MISS)
 153         (void) 0;
 154     else if (al->http.method != METHOD_GET)
 155         (void) 0;
 156     else if (mcast_miss_fd < 0)
 157         (void) 0;
 158     else {
 159         unsigned int ibuf[365];
 160         size_t isize;
 161         xstrncpy((char *) ibuf, al->url.c_str(), 364 * sizeof(int));
 162         isize = ((al->url.length() + 8) / 8) * 2;
 163
 164         if (isize > 364)
 165             isize = 364;
 166
 167         mcast_encode((unsigned int *) ibuf, isize,
 168                      (const unsigned int *) Config.mcast_miss.encode_key);
 169
 170         comm_udp_sendto(mcast_miss_fd,
 171                         &mcast_miss_to, sizeof(mcast_miss_to),
 172                         ibuf, isize * sizeof(int));
 173     }
 174
 175 #endif
 176 }
 177
 178 void
 179 accessLogRotate(void)
 180 {
 181     CustomLog *log;
 182 #if USE_FORW_VIA_DB
 183
 184     fvdbClear();
 185 #endif
 186
 187     for (log = Config.Log.accesslogs; log; log = log->next) {
 188         if (log->logfile) {
 189             int16_t rc = (log->rotateCount >= 0 ? log->rotateCount : Config.Log.rotateNumber);
 190             logfileRotate(log->logfile, rc);
 191         }
 192     }
 193
 194 #if HEADERS_LOG
 195
 196     logfileRotate(headerslog, Config.Log.rotateNumber);
 197
 198 #endif
 199 }
 200
 201 void
 202 accessLogClose(void)
 203 {
 204     CustomLog *log;
 205
 206     for (log = Config.Log.accesslogs; log; log = log->next) {
 207         if (log->logfile) {
 208             logfileClose(log->logfile);
 209             log->logfile = NULL;
 210         }
 211     }
 212
 213 #if HEADERS_LOG
 214
 215     logfileClose(headerslog);
 216
 217     headerslog = NULL;
 218
 219 #endif
 220 }
 221
 222 HierarchyLogEntry::HierarchyLogEntry() :
 223     code(HIER_NONE),
 224     cd_lookup(LOOKUP_NONE),
 225     n_choices(0),
 226     n_ichoices(0),
 227     peer_reply_status(Http::scNone),
 228     tcpServer(NULL),
 229     bodyBytesRead(-1)
 230 {
 231     memset(host, '\0', SQUIDHOSTNAMELEN);
 232     memset(cd_host, '\0', SQUIDHOSTNAMELEN);
 233
 234     peer_select_start.tv_sec =0;
 235     peer_select_start.tv_usec =0;
 236
 237     store_complete_stop.tv_sec =0;
 238     store_complete_stop.tv_usec =0;
 239
 240     clearPeerNotes();
 241
 242     totalResponseTime_.tv_sec = -1;
 243     totalResponseTime_.tv_usec = 0;
 244
 245     firstConnStart_.tv_sec = 0;
 246     firstConnStart_.tv_usec = 0;
 247 }
 248
 249 void
 250 HierarchyLogEntry::resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
 251 {
 252     clearPeerNotes();
 253
 254     tcpServer = server;
 255     if (tcpServer == NULL) {
 256         code = HIER_NONE;
 257         xstrncpy(host, requestedHost, sizeof(host));
 258     } else {
 259         code = tcpServer->peerType;
 260
 261         if (tcpServer->getPeer()) {
 262             // went to peer, log peer host name
 263             xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
 264         } else {
 265             xstrncpy(host, requestedHost, sizeof(host));
 266         }
 267     }
 268 }
 269
 270 /// forget previous notePeerRead() and notePeerWrite() calls (if any)
 271 void
 272 HierarchyLogEntry::clearPeerNotes()
 273 {
 274     peer_last_read_.tv_sec = 0;
 275     peer_last_read_.tv_usec = 0;
 276
 277     peer_last_write_.tv_sec = 0;
 278     peer_last_write_.tv_usec = 0;
 279
 280     bodyBytesRead = -1;
 281 }
 282
 283 void
 284 HierarchyLogEntry::notePeerRead()
 285 {
 286     peer_last_read_ = current_time;
 287 }
 288
 289 void
 290 HierarchyLogEntry::notePeerWrite()
 291 {
 292     peer_last_write_ = current_time;
 293 }
 294
 295 void
 296 HierarchyLogEntry::startPeerClock()
 297 {
 298     if (!firstConnStart_.tv_sec)
 299         firstConnStart_ = current_time;
 300 }
 301
 302 void
 303 HierarchyLogEntry::stopPeerClock(const bool force)
 304 {
 305     debugs(46, 5, "First connection started: " << firstConnStart_.tv_sec << "." <<
 306            std::setfill('0') << std::setw(6) << firstConnStart_.tv_usec <<
 307            ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 +  totalResponseTime_.tv_usec/1000) <<
 308            (force ? ", force fixing" : ""));
 309     if (!force && totalResponseTime_.tv_sec != -1)
 310         return;
 311
 312     if (firstConnStart_.tv_sec)
 313         tvSub(totalResponseTime_, firstConnStart_, current_time);
 314 }
 315
 316 bool
 317 HierarchyLogEntry::peerResponseTime(struct timeval &responseTime)
 318 {
 319     // no I/O whatsoever
 320     if (peer_last_write_.tv_sec <= 0 && peer_last_read_.tv_sec <= 0)
 321         return false;
 322
 323     // accommodate read without (completed) write
 324     const auto last_write = peer_last_write_.tv_sec > 0 ?
 325                             peer_last_write_ : peer_last_read_;
 326
 327     // accommodate write without (completed) read
 328     const auto last_read = peer_last_read_.tv_sec > 0 ?
 329                            peer_last_read_ : peer_last_write_;
 330
 331     tvSub(responseTime, last_write, last_read);
 332     // The peer response time (%<pt) stopwatch is currently defined to start
 333     // when we wrote the entire request. Thus, if we wrote something after the
 334     // last read, report zero peer response time.
 335     if (responseTime.tv_sec < 0) {
 336         responseTime.tv_sec = 0;
 337         responseTime.tv_usec = 0;
 338     }
 339
 340     return true;
 341 }
 342
 343 bool
 344 HierarchyLogEntry::totalResponseTime(struct timeval &responseTime)
 345 {
 346     // This should not really happen, but there may be rare code
 347     // paths that lead to FwdState discarded (or transaction logged)
 348     // without (or before) a stopPeerClock() call.
 349     if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1)
 350         stopPeerClock(false);
 351
 352     responseTime = totalResponseTime_;
 353     return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0;
 354 }
 355
 356 static void
 357 accessLogRegisterWithCacheManager(void)
 358 {
 359 #if USE_FORW_VIA_DB
 360     fvdbRegisterWithCacheManager();
 361 #endif
 362 }
 363
 364 void
 365 accessLogInit(void)
 366 {
 367     CustomLog *log;
 368
 369     accessLogRegisterWithCacheManager();
 370
 371 #if USE_ADAPTATION
 372     Log::TheConfig.hasAdaptToken = false;
 373 #endif
 374 #if ICAP_CLIENT
 375     Log::TheConfig.hasIcapToken = false;
 376 #endif
 377
 378     for (log = Config.Log.accesslogs; log; log = log->next) {
 379         if (log->type == Log::Format::CLF_NONE)
 380             continue;
 381
 382         log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal);
 383
 384         LogfileStatus = LOG_ENABLE;
 385
 386 #if USE_ADAPTATION
 387         for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) {
 388             if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES ||
 389                     curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES ||
 390                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER ||
 391                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM ||
 392                     curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS||
 393                     (curr_token->type == Format::LFT_NOTE && !Adaptation::Config::metaHeaders.empty())) {
 394                 Log::TheConfig.hasAdaptToken = true;
 395             }
 396 #if ICAP_CLIENT
 397             if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) {
 398                 Log::TheConfig.hasIcapToken = true;
 399             }
 400 #endif
 401         }
 402 #endif
 403     }
 404
 405 #if HEADERS_LOG
 406
 407     headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
 408
 409     assert(NULL != headerslog);
 410
 411 #endif
 412 #if MULTICAST_MISS_STREAM
 413
 414     if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
 415         memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
 416         mcast_miss_to.sin_family = AF_INET;
 417         mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
 418         mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
 419         mcast_miss_fd = comm_open(SOCK_DGRAM,
 420                                   IPPROTO_UDP,
 421                                   Config.Addrs.udp_incoming,
 422                                   Config.mcast_miss.port,
 423                                   COMM_NONBLOCKING,
 424                                   "Multicast Miss Stream");
 425
 426         if (mcast_miss_fd < 0)
 427             fatal("Cannot open Multicast Miss Stream Socket");
 428
 429         debugs(46, DBG_IMPORTANT, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd);
 430
 431         mcastSetTtl(mcast_miss_fd, Config.mcast_miss.ttl);
 432
 433         if (strlen(Config.mcast_miss.encode_key) < 16)
 434             fatal("mcast_encode_key is too short, must be 16 characters");
 435     }
 436
 437 #endif
 438 #if USE_FORW_VIA_DB
 439
 440     fvdbInit();
 441
 442 #endif
 443 }
 444
 445 #if USE_FORW_VIA_DB
 446
 447 static void
 448 fvdbInit(void)
 449 {
 450     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 451     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 452 }
 453
 454 static void
 455 fvdbRegisterWithCacheManager(void)
 456 {
 457     Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
 458     Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
 459                         fvdbDumpForw, 0, 1);
 460 }
 461
 462 static void
 463 fvdbCount(hash_table * hash, const char *key)
 464 {
 465     fvdb_entry *fv;
 466
 467     if (NULL == hash)
 468         return;
 469
 470     fv = (fvdb_entry *)hash_lookup(hash, key);
 471
 472     if (NULL == fv) {
 473         fv = static_cast <fvdb_entry *>(xcalloc(1, sizeof(fvdb_entry)));
 474         fv->hash.key = xstrdup(key);
 475         hash_join(hash, &fv->hash);
 476     }
 477
 478     ++ fv->n;
 479 }
 480
 481 void
 482 fvdbCountVia(const char *key)
 483 {
 484     fvdbCount(via_table, key);
 485 }
 486
 487 void
 488 fvdbCountForw(const char *key)
 489 {
 490     fvdbCount(forw_table, key);
 491 }
 492
 493 static void
 494 fvdbDumpTable(StoreEntry * e, hash_table * hash)
 495 {
 496     hash_link *h;
 497     fvdb_entry *fv;
 498
 499     if (hash == NULL)
 500         return;
 501
 502     hash_first(hash);
 503
 504     while ((h = hash_next(hash))) {
 505         fv = (fvdb_entry *) h;
 506         storeAppendPrintf(e, "%9d %s\n", fv->n, hashKeyStr(&fv->hash));
 507     }
 508 }
 509
 510 static void
 511 fvdbDumpVia(StoreEntry * e)
 512 {
 513     fvdbDumpTable(e, via_table);
 514 }
 515
 516 static void
 517 fvdbDumpForw(StoreEntry * e)
 518 {
 519     fvdbDumpTable(e, forw_table);
 520 }
 521
 522 static
 523 void
 524 fvdbFreeEntry(void *data)
 525 {
 526     fvdb_entry *fv = static_cast <fvdb_entry *>(data);
 527     xfree(fv->hash.key);
 528     xfree(fv);
 529 }
 530
 531 static void
 532 fvdbClear(void)
 533 {
 534     hashFreeItems(via_table, fvdbFreeEntry);
 535     hashFreeMemory(via_table);
 536     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 537     hashFreeItems(forw_table, fvdbFreeEntry);
 538     hashFreeMemory(forw_table);
 539     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 540 }
 541
 542 #endif
 543
 544 #if MULTICAST_MISS_STREAM
 545 /*
 546  * From http://www.io.com/~paulhart/game/algorithms/tea.html
 547  *
 548  * size of 'ibuf' must be a multiple of 2.
 549  * size of 'key' must be 4.
 550  * 'ibuf' is modified in place, encrypted data is written in
 551  * network byte order.
 552  */
 553 static void
 554 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
 555 {
 556     unsigned int y;
 557     unsigned int z;
 558     unsigned int sum;
 559     const unsigned int delta = 0x9e3779b9;
 560     unsigned int n = 32;
 561     const unsigned int k0 = htonl(key[0]);
 562     const unsigned int k1 = htonl(key[1]);
 563     const unsigned int k2 = htonl(key[2]);
 564     const unsigned int k3 = htonl(key[3]);
 565     int i;
 566
 567     for (i = 0; i < isize; i += 2) {
 568         y = htonl(ibuf[i]);
 569         z = htonl(ibuf[i + 1]);
 570         sum = 0;
 571
 572         for (n = 32; n; --n) {
 573             sum += delta;
 574             y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
 575             z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
 576         }
 577
 578         ibuf[i] = htonl(y);
 579         ibuf[i + 1] = htonl(z);
 580     }
 581 }
 582
 583 #endif
 584
 585 #if HEADERS_LOG
 586 void
 587 headersLog(int cs, int pq, const HttpRequestMethod& method, void *data)
 588 {
 589     HttpReply *rep;
 590     HttpRequest *req;
 591     unsigned short magic = 0;
 592     unsigned char M = (unsigned char) m;
 593     char *hmask;
 594     int ccmask = 0;
 595
 596     if (0 == pq) {
 597         /* reply */
 598         rep = data;
 599         req = NULL;
 600         magic = 0x0050;
 601         hmask = rep->header.mask;
 602
 603         if (rep->cache_control)
 604             ccmask = rep->cache_control->mask;
 605     } else {
 606         /* request */
 607         req = data;
 608         rep = NULL;
 609         magic = 0x0051;
 610         hmask = req->header.mask;
 611
 612         if (req->cache_control)
 613             ccmask = req->cache_control->mask;
 614     }
 615
 616     if (0 == cs) {
 617         /* client */
 618         magic |= 0x4300;
 619     } else {
 620         /* server */
 621         magic |= 0x5300;
 622     }
 623
 624     magic = htons(magic);
 625     ccmask = htonl(ccmask);
 626
 627     unsigned short S = 0;
 628     if (0 == pq)
 629         S = static_cast<unsigned short>(rep->sline.status());
 630
 631     logfileWrite(headerslog, &magic, sizeof(magic));
 632     logfileWrite(headerslog, &M, sizeof(M));
 633     logfileWrite(headerslog, &S, sizeof(S));
 634     logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
 635     logfileWrite(headerslog, &ccmask, sizeof(int));
 636 }
 637
 638 #endif
 639