src/log/access_log.cc

   1 /*
   2  * Copyright (C) 1996-2020 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 "error/Detail.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_ <<
 306            ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 +  totalResponseTime_.tv_usec/1000) <<
 307            (force ? ", force fixing" : ""));
 308     if (!force && totalResponseTime_.tv_sec != -1)
 309         return;
 310
 311     if (firstConnStart_.tv_sec)
 312         tvSub(totalResponseTime_, firstConnStart_, current_time);
 313 }
 314
 315 bool
 316 HierarchyLogEntry::peerResponseTime(struct timeval &responseTime)
 317 {
 318     // no I/O whatsoever
 319     if (peer_last_write_.tv_sec <= 0 && peer_last_read_.tv_sec <= 0)
 320         return false;
 321
 322     // accommodate read without (completed) write
 323     const auto last_write = peer_last_write_.tv_sec > 0 ?
 324                             peer_last_write_ : peer_last_read_;
 325
 326     // accommodate write without (completed) read
 327     const auto last_read = peer_last_read_.tv_sec > 0 ?
 328                            peer_last_read_ : peer_last_write_;
 329
 330     tvSub(responseTime, last_write, last_read);
 331     // The peer response time (%<pt) stopwatch is currently defined to start
 332     // when we wrote the entire request. Thus, if we wrote something after the
 333     // last read, report zero peer response time.
 334     if (responseTime.tv_sec < 0) {
 335         responseTime.tv_sec = 0;
 336         responseTime.tv_usec = 0;
 337     }
 338
 339     return true;
 340 }
 341
 342 bool
 343 HierarchyLogEntry::totalResponseTime(struct timeval &responseTime)
 344 {
 345     // This should not really happen, but there may be rare code
 346     // paths that lead to FwdState discarded (or transaction logged)
 347     // without (or before) a stopPeerClock() call.
 348     if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1)
 349         stopPeerClock(false);
 350
 351     responseTime = totalResponseTime_;
 352     return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0;
 353 }
 354
 355 static void
 356 accessLogRegisterWithCacheManager(void)
 357 {
 358 #if USE_FORW_VIA_DB
 359     fvdbRegisterWithCacheManager();
 360 #endif
 361 }
 362
 363 void
 364 accessLogInit(void)
 365 {
 366     CustomLog *log;
 367
 368     accessLogRegisterWithCacheManager();
 369
 370 #if USE_ADAPTATION
 371     Log::TheConfig.hasAdaptToken = false;
 372 #endif
 373 #if ICAP_CLIENT
 374     Log::TheConfig.hasIcapToken = false;
 375 #endif
 376
 377     for (log = Config.Log.accesslogs; log; log = log->next) {
 378         if (log->type == Log::Format::CLF_NONE)
 379             continue;
 380
 381         log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal);
 382
 383         LogfileStatus = LOG_ENABLE;
 384
 385 #if USE_ADAPTATION
 386         for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) {
 387             if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES ||
 388                     curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES ||
 389                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER ||
 390                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM ||
 391                     curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS||
 392                     (curr_token->type == Format::LFT_NOTE && !Adaptation::Config::metaHeaders.empty())) {
 393                 Log::TheConfig.hasAdaptToken = true;
 394             }
 395 #if ICAP_CLIENT
 396             if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) {
 397                 Log::TheConfig.hasIcapToken = true;
 398             }
 399 #endif
 400         }
 401 #endif
 402     }
 403
 404 #if HEADERS_LOG
 405
 406     headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
 407
 408     assert(NULL != headerslog);
 409
 410 #endif
 411 #if MULTICAST_MISS_STREAM
 412
 413     if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
 414         memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
 415         mcast_miss_to.sin_family = AF_INET;
 416         mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
 417         mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
 418         mcast_miss_fd = comm_open(SOCK_DGRAM,
 419                                   IPPROTO_UDP,
 420                                   Config.Addrs.udp_incoming,
 421                                   Config.mcast_miss.port,
 422                                   COMM_NONBLOCKING,
 423                                   "Multicast Miss Stream");
 424
 425         if (mcast_miss_fd < 0)
 426             fatal("Cannot open Multicast Miss Stream Socket");
 427
 428         debugs(46, DBG_IMPORTANT, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd);
 429
 430         mcastSetTtl(mcast_miss_fd, Config.mcast_miss.ttl);
 431
 432         if (strlen(Config.mcast_miss.encode_key) < 16)
 433             fatal("mcast_encode_key is too short, must be 16 characters");
 434     }
 435
 436 #endif
 437 #if USE_FORW_VIA_DB
 438
 439     fvdbInit();
 440
 441 #endif
 442 }
 443
 444 #if USE_FORW_VIA_DB
 445
 446 static void
 447 fvdbInit(void)
 448 {
 449     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 450     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 451 }
 452
 453 static void
 454 fvdbRegisterWithCacheManager(void)
 455 {
 456     Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
 457     Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
 458                         fvdbDumpForw, 0, 1);
 459 }
 460
 461 static void
 462 fvdbCount(hash_table * hash, const char *key)
 463 {
 464     fvdb_entry *fv;
 465
 466     if (NULL == hash)
 467         return;
 468
 469     fv = (fvdb_entry *)hash_lookup(hash, key);
 470
 471     if (NULL == fv) {
 472         fv = static_cast <fvdb_entry *>(xcalloc(1, sizeof(fvdb_entry)));
 473         fv->hash.key = xstrdup(key);
 474         hash_join(hash, &fv->hash);
 475     }
 476
 477     ++ fv->n;
 478 }
 479
 480 void
 481 fvdbCountVia(const char *key)
 482 {
 483     fvdbCount(via_table, key);
 484 }
 485
 486 void
 487 fvdbCountForw(const char *key)
 488 {
 489     fvdbCount(forw_table, key);
 490 }
 491
 492 static void
 493 fvdbDumpTable(StoreEntry * e, hash_table * hash)
 494 {
 495     hash_link *h;
 496     fvdb_entry *fv;
 497
 498     if (hash == NULL)
 499         return;
 500
 501     hash_first(hash);
 502
 503     while ((h = hash_next(hash))) {
 504         fv = (fvdb_entry *) h;
 505         storeAppendPrintf(e, "%9d %s\n", fv->n, hashKeyStr(&fv->hash));
 506     }
 507 }
 508
 509 static void
 510 fvdbDumpVia(StoreEntry * e)
 511 {
 512     fvdbDumpTable(e, via_table);
 513 }
 514
 515 static void
 516 fvdbDumpForw(StoreEntry * e)
 517 {
 518     fvdbDumpTable(e, forw_table);
 519 }
 520
 521 static
 522 void
 523 fvdbFreeEntry(void *data)
 524 {
 525     fvdb_entry *fv = static_cast <fvdb_entry *>(data);
 526     xfree(fv->hash.key);
 527     xfree(fv);
 528 }
 529
 530 static void
 531 fvdbClear(void)
 532 {
 533     hashFreeItems(via_table, fvdbFreeEntry);
 534     hashFreeMemory(via_table);
 535     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 536     hashFreeItems(forw_table, fvdbFreeEntry);
 537     hashFreeMemory(forw_table);
 538     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 539 }
 540
 541 #endif
 542
 543 #if MULTICAST_MISS_STREAM
 544 /*
 545  * From http://www.io.com/~paulhart/game/algorithms/tea.html
 546  *
 547  * size of 'ibuf' must be a multiple of 2.
 548  * size of 'key' must be 4.
 549  * 'ibuf' is modified in place, encrypted data is written in
 550  * network byte order.
 551  */
 552 static void
 553 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
 554 {
 555     unsigned int y;
 556     unsigned int z;
 557     unsigned int sum;
 558     const unsigned int delta = 0x9e3779b9;
 559     unsigned int n = 32;
 560     const unsigned int k0 = htonl(key[0]);
 561     const unsigned int k1 = htonl(key[1]);
 562     const unsigned int k2 = htonl(key[2]);
 563     const unsigned int k3 = htonl(key[3]);
 564     int i;
 565
 566     for (i = 0; i < isize; i += 2) {
 567         y = htonl(ibuf[i]);
 568         z = htonl(ibuf[i + 1]);
 569         sum = 0;
 570
 571         for (n = 32; n; --n) {
 572             sum += delta;
 573             y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
 574             z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
 575         }
 576
 577         ibuf[i] = htonl(y);
 578         ibuf[i + 1] = htonl(z);
 579     }
 580 }
 581
 582 #endif
 583
 584 #if HEADERS_LOG
 585 void
 586 headersLog(int cs, int pq, const HttpRequestMethod& method, void *data)
 587 {
 588     HttpReply *rep;
 589     HttpRequest *req;
 590     unsigned short magic = 0;
 591     unsigned char M = (unsigned char) m;
 592     char *hmask;
 593     int ccmask = 0;
 594
 595     if (0 == pq) {
 596         /* reply */
 597         rep = data;
 598         req = NULL;
 599         magic = 0x0050;
 600         hmask = rep->header.mask;
 601
 602         if (rep->cache_control)
 603             ccmask = rep->cache_control->mask;
 604     } else {
 605         /* request */
 606         req = data;
 607         rep = NULL;
 608         magic = 0x0051;
 609         hmask = req->header.mask;
 610
 611         if (req->cache_control)
 612             ccmask = req->cache_control->mask;
 613     }
 614
 615     if (0 == cs) {
 616         /* client */
 617         magic |= 0x4300;
 618     } else {
 619         /* server */
 620         magic |= 0x5300;
 621     }
 622
 623     magic = htons(magic);
 624     ccmask = htonl(ccmask);
 625
 626     unsigned short S = 0;
 627     if (0 == pq)
 628         S = static_cast<unsigned short>(rep->sline.status());
 629
 630     logfileWrite(headerslog, &magic, sizeof(magic));
 631     logfileWrite(headerslog, &M, sizeof(M));
 632     logfileWrite(headerslog, &S, sizeof(S));
 633     logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
 634     logfileWrite(headerslog, &ccmask, sizeof(int));
 635 }
 636
 637 #endif
 638