src/log/access_log.cc

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