src/log/access_log.cc

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