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 #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
accessLogLogTo(CustomLog * log,AccessLogEntry::Pointer & al,ACLChecklist * checklist)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
accessLogLog(AccessLogEntry::Pointer & al,ACLChecklist * checklist)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
accessLogRotate(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
accessLogClose(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
HierarchyLogEntry()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
resetPeerNotes(const Comm::ConnectionPointer & server,const char * requestedHost)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
clearPeerNotes()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
notePeerRead()284 HierarchyLogEntry::notePeerRead()
285 {
286 peer_last_read_ = current_time;
287 }
288
289 void
notePeerWrite()290 HierarchyLogEntry::notePeerWrite()
291 {
292 peer_last_write_ = current_time;
293 }
294
295 void
startPeerClock()296 HierarchyLogEntry::startPeerClock()
297 {
298 if (!firstConnStart_.tv_sec)
299 firstConnStart_ = current_time;
300 }
301
302 void
stopPeerClock(const bool force)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
peerResponseTime(struct timeval & responseTime)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
totalResponseTime(struct timeval & responseTime)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
accessLogRegisterWithCacheManager(void)357 accessLogRegisterWithCacheManager(void)
358 {
359 #if USE_FORW_VIA_DB
360 fvdbRegisterWithCacheManager();
361 #endif
362 }
363
364 void
accessLogInit(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
fvdbInit(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
fvdbRegisterWithCacheManager(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
fvdbCount(hash_table * hash,const char * key)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
fvdbCountVia(const char * key)482 fvdbCountVia(const char *key)
483 {
484 fvdbCount(via_table, key);
485 }
486
487 void
fvdbCountForw(const char * key)488 fvdbCountForw(const char *key)
489 {
490 fvdbCount(forw_table, key);
491 }
492
493 static void
fvdbDumpTable(StoreEntry * e,hash_table * hash)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
fvdbDumpVia(StoreEntry * e)511 fvdbDumpVia(StoreEntry * e)
512 {
513 fvdbDumpTable(e, via_table);
514 }
515
516 static void
fvdbDumpForw(StoreEntry * e)517 fvdbDumpForw(StoreEntry * e)
518 {
519 fvdbDumpTable(e, forw_table);
520 }
521
522 static
523 void
fvdbFreeEntry(void * data)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
fvdbClear(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
mcast_encode(unsigned int * ibuf,size_t isize,const unsigned int * key)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
headersLog(int cs,int pq,const HttpRequestMethod & method,void * data)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
640