src/log/access_log.cc

   1 /*
   2  * Copyright (C) 1996-2021 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 #include "sbuf/Algorithms.h"
  15 #if USE_ADAPTATION
  16 #include "adaptation/Config.h"
  17 #endif
  18 #include "base/PackableStream.h"
  19 #include "CachePeer.h"
  20 #include "error/Detail.h"
  21 #include "errorpage.h"
  22 #include "format/Token.h"
  23 #include "globals.h"
  24 #include "hier_code.h"
  25 #include "HttpReply.h"
  26 #include "HttpRequest.h"
  27 #include "log/access_log.h"
  28 #include "log/Config.h"
  29 #include "log/CustomLog.h"
  30 #include "log/File.h"
  31 #include "log/Formats.h"
  32 #include "MemBuf.h"
  33 #include "mgr/Registration.h"
  34 #include "rfc1738.h"
  35 #include "sbuf/SBuf.h"
  36 #include "SquidConfig.h"
  37 #include "SquidTime.h"
  38 #include "Store.h"
  39
  40 #if USE_SQUID_EUI
  41 #include "eui/Eui48.h"
  42 #include "eui/Eui64.h"
  43 #endif
  44
  45 #include <unordered_map>
  46
  47 #if HEADERS_LOG
  48 static Logfile *headerslog = NULL;
  49 #endif
  50
  51 #if MULTICAST_MISS_STREAM
  52 static int mcast_miss_fd = -1;
  53
  54 static struct sockaddr_in mcast_miss_to;
  55 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
  56 #endif
  57
  58 #if USE_FORW_VIA_DB
  59
  60 using HeaderValueCountsElement = std::pair<SBuf, uint64_t>;
  61 /// counts the number of header field value occurrences
  62 using HeaderValueCounts = std::unordered_map<SBuf, uint64_t, std::hash<SBuf>, std::equal_to<SBuf>, PoolingAllocator<HeaderValueCountsElement> >;
  63
  64 /// counts the number of HTTP Via header field value occurrences
  65 static HeaderValueCounts TheViaCounts;
  66 /// counts the number of HTTP X-Forwarded-For header field value occurrences
  67 static HeaderValueCounts TheForwardedCounts;
  68
  69 static OBJH fvdbDumpVia;
  70 static OBJH fvdbDumpForwarded;
  71 static void fvdbClear(void);
  72 static void fvdbRegisterWithCacheManager();
  73 #endif
  74
  75 int LogfileStatus = LOG_DISABLE;
  76
  77 void
  78 accessLogLogTo(CustomLog *log, const AccessLogEntryPointer &al, ACLChecklist *checklist)
  79 {
  80
  81     if (al->url.isEmpty())
  82         al->url = Format::Dash;
  83
  84     if (!al->http.content_type || *al->http.content_type == '\0')
  85         al->http.content_type = dash_str;
  86
  87     if (al->hier.host[0] == '\0')
  88         xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
  89
  90     for (; log; log = log->next) {
  91         if (log->aclList && checklist && !checklist->fastCheck(log->aclList).allowed())
  92             continue;
  93
  94         // The special-case "none" type has no logfile object set
  95         if (log->type == Log::Format::CLF_NONE)
  96             return;
  97
  98         if (log->logfile) {
  99             logfileLineStart(log->logfile);
 100
 101             switch (log->type) {
 102
 103             case Log::Format::CLF_SQUID:
 104                 Log::Format::SquidNative(al, log->logfile);
 105                 break;
 106
 107             case Log::Format::CLF_COMBINED:
 108                 Log::Format::HttpdCombined(al, log->logfile);
 109                 break;
 110
 111             case Log::Format::CLF_COMMON:
 112                 Log::Format::HttpdCommon(al, log->logfile);
 113                 break;
 114
 115             case Log::Format::CLF_REFERER:
 116                 Log::Format::SquidReferer(al, log->logfile);
 117                 break;
 118
 119             case Log::Format::CLF_USERAGENT:
 120                 Log::Format::SquidUserAgent(al, log->logfile);
 121                 break;
 122
 123             case Log::Format::CLF_CUSTOM:
 124                 Log::Format::SquidCustom(al, log);
 125                 break;
 126
 127 #if ICAP_CLIENT
 128             case Log::Format::CLF_ICAP_SQUID:
 129                 Log::Format::SquidIcap(al, log->logfile);
 130                 break;
 131 #endif
 132
 133             default:
 134                 fatalf("Unknown log format %d\n", log->type);
 135                 break;
 136             }
 137
 138             logfileLineEnd(log->logfile);
 139         }
 140
 141         // NP:  WTF?  if _any_ log line has no checklist ignore the following ones?
 142         if (!checklist)
 143             break;
 144     }
 145 }
 146
 147 void
 148 accessLogLog(const AccessLogEntryPointer &al, ACLChecklist *checklist)
 149 {
 150     if (LogfileStatus != LOG_ENABLE)
 151         return;
 152
 153     accessLogLogTo(Config.Log.accesslogs, al, checklist);
 154 #if MULTICAST_MISS_STREAM
 155
 156     if (al->cache.code != LOG_TCP_MISS)
 157         (void) 0;
 158     else if (al->http.method != METHOD_GET)
 159         (void) 0;
 160     else if (mcast_miss_fd < 0)
 161         (void) 0;
 162     else {
 163         unsigned int ibuf[365];
 164         size_t isize;
 165         xstrncpy((char *) ibuf, al->url.c_str(), 364 * sizeof(int));
 166         isize = ((al->url.length() + 8) / 8) * 2;
 167
 168         if (isize > 364)
 169             isize = 364;
 170
 171         mcast_encode((unsigned int *) ibuf, isize,
 172                      (const unsigned int *) Config.mcast_miss.encode_key);
 173
 174         comm_udp_sendto(mcast_miss_fd,
 175                         &mcast_miss_to, sizeof(mcast_miss_to),
 176                         ibuf, isize * sizeof(int));
 177     }
 178
 179 #endif
 180 }
 181
 182 void
 183 accessLogRotate(void)
 184 {
 185     CustomLog *log;
 186 #if USE_FORW_VIA_DB
 187
 188     fvdbClear();
 189 #endif
 190
 191     for (log = Config.Log.accesslogs; log; log = log->next) {
 192         log->rotate();
 193     }
 194
 195 #if HEADERS_LOG
 196
 197     logfileRotate(headerslog, Config.Log.rotateNumber);
 198
 199 #endif
 200 }
 201
 202 void
 203 accessLogClose(void)
 204 {
 205     CustomLog *log;
 206
 207     for (log = Config.Log.accesslogs; log; log = log->next) {
 208         if (log->logfile) {
 209             logfileClose(log->logfile);
 210             log->logfile = NULL;
 211         }
 212     }
 213
 214 #if HEADERS_LOG
 215
 216     logfileClose(headerslog);
 217
 218     headerslog = NULL;
 219
 220 #endif
 221 }
 222
 223 HierarchyLogEntry::HierarchyLogEntry() :
 224     code(HIER_NONE),
 225     cd_lookup(LOOKUP_NONE),
 226     n_choices(0),
 227     n_ichoices(0),
 228     peer_reply_status(Http::scNone),
 229     tcpServer(NULL),
 230     bodyBytesRead(-1)
 231 {
 232     memset(host, '\0', SQUIDHOSTNAMELEN);
 233     memset(cd_host, '\0', SQUIDHOSTNAMELEN);
 234
 235     peer_select_start.tv_sec =0;
 236     peer_select_start.tv_usec =0;
 237
 238     store_complete_stop.tv_sec =0;
 239     store_complete_stop.tv_usec =0;
 240
 241     clearPeerNotes();
 242
 243     totalResponseTime_.tv_sec = -1;
 244     totalResponseTime_.tv_usec = 0;
 245
 246     firstConnStart_.tv_sec = 0;
 247     firstConnStart_.tv_usec = 0;
 248 }
 249
 250 void
 251 HierarchyLogEntry::resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
 252 {
 253     clearPeerNotes();
 254
 255     tcpServer = server;
 256     if (tcpServer == NULL) {
 257         code = HIER_NONE;
 258         xstrncpy(host, requestedHost, sizeof(host));
 259     } else {
 260         code = tcpServer->peerType;
 261
 262         if (tcpServer->getPeer()) {
 263             // went to peer, log peer host name
 264             xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
 265         } else {
 266             xstrncpy(host, requestedHost, sizeof(host));
 267         }
 268     }
 269 }
 270
 271 /// forget previous notePeerRead() and notePeerWrite() calls (if any)
 272 void
 273 HierarchyLogEntry::clearPeerNotes()
 274 {
 275     peer_last_read_.tv_sec = 0;
 276     peer_last_read_.tv_usec = 0;
 277
 278     peer_last_write_.tv_sec = 0;
 279     peer_last_write_.tv_usec = 0;
 280
 281     bodyBytesRead = -1;
 282 }
 283
 284 void
 285 HierarchyLogEntry::notePeerRead()
 286 {
 287     peer_last_read_ = current_time;
 288 }
 289
 290 void
 291 HierarchyLogEntry::notePeerWrite()
 292 {
 293     peer_last_write_ = current_time;
 294 }
 295
 296 void
 297 HierarchyLogEntry::startPeerClock()
 298 {
 299     if (!firstConnStart_.tv_sec)
 300         firstConnStart_ = current_time;
 301 }
 302
 303 void
 304 HierarchyLogEntry::stopPeerClock(const bool force)
 305 {
 306     debugs(46, 5, "First connection started: " << firstConnStart_ <<
 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 }
 439
 440 #if USE_FORW_VIA_DB
 441
 442 static void
 443 fvdbRegisterWithCacheManager(void)
 444 {
 445     Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
 446     Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
 447                         fvdbDumpForwarded, 0, 1);
 448 }
 449
 450 void
 451 fvdbCountVia(const SBuf &headerValue)
 452 {
 453     ++TheViaCounts[headerValue];
 454 }
 455
 456 void
 457 fvdbCountForwarded(const SBuf &key)
 458 {
 459     ++TheForwardedCounts[key];
 460 }
 461
 462 static void
 463 fvdbDumpCounts(StoreEntry &e, const HeaderValueCounts &counts)
 464 {
 465     PackableStream os(e);
 466     for (const auto &i : counts)
 467         os << std::setw(9) << i.second << ' ' << i.first << "\n";
 468 }
 469
 470 static void
 471 fvdbDumpVia(StoreEntry * e)
 472 {
 473     assert(e);
 474     fvdbDumpCounts(*e, TheViaCounts);
 475 }
 476
 477 static void
 478 fvdbDumpForwarded(StoreEntry * e)
 479 {
 480     assert(e);
 481     fvdbDumpCounts(*e, TheForwardedCounts);
 482 }
 483
 484 static void
 485 fvdbClear(void)
 486 {
 487     TheViaCounts.clear();
 488     TheForwardedCounts.clear();
 489 }
 490
 491 #endif
 492
 493 #if MULTICAST_MISS_STREAM
 494 /*
 495  * From http://www.io.com/~paulhart/game/algorithms/tea.html
 496  *
 497  * size of 'ibuf' must be a multiple of 2.
 498  * size of 'key' must be 4.
 499  * 'ibuf' is modified in place, encrypted data is written in
 500  * network byte order.
 501  */
 502 static void
 503 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
 504 {
 505     unsigned int y;
 506     unsigned int z;
 507     unsigned int sum;
 508     const unsigned int delta = 0x9e3779b9;
 509     unsigned int n = 32;
 510     const unsigned int k0 = htonl(key[0]);
 511     const unsigned int k1 = htonl(key[1]);
 512     const unsigned int k2 = htonl(key[2]);
 513     const unsigned int k3 = htonl(key[3]);
 514     int i;
 515
 516     for (i = 0; i < isize; i += 2) {
 517         y = htonl(ibuf[i]);
 518         z = htonl(ibuf[i + 1]);
 519         sum = 0;
 520
 521         for (n = 32; n; --n) {
 522             sum += delta;
 523             y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
 524             z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
 525         }
 526
 527         ibuf[i] = htonl(y);
 528         ibuf[i + 1] = htonl(z);
 529     }
 530 }
 531
 532 #endif
 533
 534 #if HEADERS_LOG
 535 void
 536 headersLog(int cs, int pq, const HttpRequestMethod& method, void *data)
 537 {
 538     HttpReply *rep;
 539     HttpRequest *req;
 540     unsigned short magic = 0;
 541     unsigned char M = (unsigned char) m;
 542     char *hmask;
 543     int ccmask = 0;
 544
 545     if (0 == pq) {
 546         /* reply */
 547         rep = data;
 548         req = NULL;
 549         magic = 0x0050;
 550         hmask = rep->header.mask;
 551
 552         if (rep->cache_control)
 553             ccmask = rep->cache_control->mask;
 554     } else {
 555         /* request */
 556         req = data;
 557         rep = NULL;
 558         magic = 0x0051;
 559         hmask = req->header.mask;
 560
 561         if (req->cache_control)
 562             ccmask = req->cache_control->mask;
 563     }
 564
 565     if (0 == cs) {
 566         /* client */
 567         magic |= 0x4300;
 568     } else {
 569         /* server */
 570         magic |= 0x5300;
 571     }
 572
 573     magic = htons(magic);
 574     ccmask = htonl(ccmask);
 575
 576     unsigned short S = 0;
 577     if (0 == pq)
 578         S = static_cast<unsigned short>(rep->sline.status());
 579
 580     logfileWrite(headerslog, &magic, sizeof(magic));
 581     logfileWrite(headerslog, &M, sizeof(M));
 582     logfileWrite(headerslog, &S, sizeof(S));
 583     logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
 584     logfileWrite(headerslog, &ccmask, sizeof(int));
 585 }
 586
 587 #endif
 588