2 * Copyright (C) 1996-2021 The Squid Software Foundation and contributors
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.
9 /* DEBUG: section 46 Access Log */
12 #include "AccessLogEntry.h"
13 #include "acl/Checklist.h"
14 #include "sbuf/Algorithms.h"
16 #include "adaptation/Config.h"
18 #include "base/PackableStream.h"
19 #include "CachePeer.h"
20 #include "error/Detail.h"
21 #include "errorpage.h"
22 #include "format/Token.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"
31 #include "log/Formats.h"
33 #include "mgr/Registration.h"
35 #include "sbuf/SBuf.h"
36 #include "SquidConfig.h"
37 #include "SquidTime.h"
41 #include "eui/Eui48.h"
42 #include "eui/Eui64.h"
45 #include <unordered_map>
48 static Logfile
*headerslog
= NULL
;
51 #if MULTICAST_MISS_STREAM
52 static int mcast_miss_fd
= -1;
54 static struct sockaddr_in mcast_miss_to
;
55 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
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
> >;
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
;
69 static OBJH fvdbDumpVia
;
70 static OBJH fvdbDumpForwarded
;
71 static void fvdbClear(void);
72 static void fvdbRegisterWithCacheManager();
75 int LogfileStatus
= LOG_DISABLE
;
78 accessLogLogTo(CustomLog
* log
, AccessLogEntry::Pointer
&al
, ACLChecklist
* checklist
)
81 if (al
->url
.isEmpty())
82 al
->url
= Format::Dash
;
84 if (!al
->http
.content_type
|| *al
->http
.content_type
== '\0')
85 al
->http
.content_type
= dash_str
;
87 if (al
->hier
.host
[0] == '\0')
88 xstrncpy(al
->hier
.host
, dash_str
, SQUIDHOSTNAMELEN
);
90 for (; log
; log
= log
->next
) {
91 if (log
->aclList
&& checklist
&& !checklist
->fastCheck(log
->aclList
).allowed())
94 // The special-case "none" type has no logfile object set
95 if (log
->type
== Log::Format::CLF_NONE
)
99 logfileLineStart(log
->logfile
);
103 case Log::Format::CLF_SQUID
:
104 Log::Format::SquidNative(al
, log
->logfile
);
107 case Log::Format::CLF_COMBINED
:
108 Log::Format::HttpdCombined(al
, log
->logfile
);
111 case Log::Format::CLF_COMMON
:
112 Log::Format::HttpdCommon(al
, log
->logfile
);
115 case Log::Format::CLF_REFERER
:
116 Log::Format::SquidReferer(al
, log
->logfile
);
119 case Log::Format::CLF_USERAGENT
:
120 Log::Format::SquidUserAgent(al
, log
->logfile
);
123 case Log::Format::CLF_CUSTOM
:
124 Log::Format::SquidCustom(al
, log
);
128 case Log::Format::CLF_ICAP_SQUID
:
129 Log::Format::SquidIcap(al
, log
->logfile
);
134 fatalf("Unknown log format %d\n", log
->type
);
138 logfileLineEnd(log
->logfile
);
141 // NP: WTF? if _any_ log line has no checklist ignore the following ones?
148 accessLogLog(AccessLogEntry::Pointer
&al
, ACLChecklist
* checklist
)
150 if (LogfileStatus
!= LOG_ENABLE
)
153 accessLogLogTo(Config
.Log
.accesslogs
, al
, checklist
);
154 #if MULTICAST_MISS_STREAM
156 if (al
->cache
.code
!= LOG_TCP_MISS
)
158 else if (al
->http
.method
!= METHOD_GET
)
160 else if (mcast_miss_fd
< 0)
163 unsigned int ibuf
[365];
165 xstrncpy((char *) ibuf
, al
->url
.c_str(), 364 * sizeof(int));
166 isize
= ((al
->url
.length() + 8) / 8) * 2;
171 mcast_encode((unsigned int *) ibuf
, isize
,
172 (const unsigned int *) Config
.mcast_miss
.encode_key
);
174 comm_udp_sendto(mcast_miss_fd
,
175 &mcast_miss_to
, sizeof(mcast_miss_to
),
176 ibuf
, isize
* sizeof(int));
183 accessLogRotate(void)
191 for (log
= Config
.Log
.accesslogs
; log
; log
= log
->next
) {
197 logfileRotate(headerslog
, Config
.Log
.rotateNumber
);
207 for (log
= Config
.Log
.accesslogs
; log
; log
= log
->next
) {
209 logfileClose(log
->logfile
);
216 logfileClose(headerslog
);
223 HierarchyLogEntry::HierarchyLogEntry() :
225 cd_lookup(LOOKUP_NONE
),
228 peer_reply_status(Http::scNone
),
232 memset(host
, '\0', SQUIDHOSTNAMELEN
);
233 memset(cd_host
, '\0', SQUIDHOSTNAMELEN
);
235 peer_select_start
.tv_sec
=0;
236 peer_select_start
.tv_usec
=0;
238 store_complete_stop
.tv_sec
=0;
239 store_complete_stop
.tv_usec
=0;
243 totalResponseTime_
.tv_sec
= -1;
244 totalResponseTime_
.tv_usec
= 0;
246 firstConnStart_
.tv_sec
= 0;
247 firstConnStart_
.tv_usec
= 0;
251 HierarchyLogEntry::resetPeerNotes(const Comm::ConnectionPointer
&server
, const char *requestedHost
)
256 if (tcpServer
== NULL
) {
258 xstrncpy(host
, requestedHost
, sizeof(host
));
260 code
= tcpServer
->peerType
;
262 if (tcpServer
->getPeer()) {
263 // went to peer, log peer host name
264 xstrncpy(host
, tcpServer
->getPeer()->name
, sizeof(host
));
266 xstrncpy(host
, requestedHost
, sizeof(host
));
271 /// forget previous notePeerRead() and notePeerWrite() calls (if any)
273 HierarchyLogEntry::clearPeerNotes()
275 peer_last_read_
.tv_sec
= 0;
276 peer_last_read_
.tv_usec
= 0;
278 peer_last_write_
.tv_sec
= 0;
279 peer_last_write_
.tv_usec
= 0;
285 HierarchyLogEntry::notePeerRead()
287 peer_last_read_
= current_time
;
291 HierarchyLogEntry::notePeerWrite()
293 peer_last_write_
= current_time
;
297 HierarchyLogEntry::startPeerClock()
299 if (!firstConnStart_
.tv_sec
)
300 firstConnStart_
= current_time
;
304 HierarchyLogEntry::stopPeerClock(const bool force
)
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)
312 if (firstConnStart_
.tv_sec
)
313 tvSub(totalResponseTime_
, firstConnStart_
, current_time
);
317 HierarchyLogEntry::peerResponseTime(struct timeval
&responseTime
)
320 if (peer_last_write_
.tv_sec
<= 0 && peer_last_read_
.tv_sec
<= 0)
323 // accommodate read without (completed) write
324 const auto last_write
= peer_last_write_
.tv_sec
> 0 ?
325 peer_last_write_
: peer_last_read_
;
327 // accommodate write without (completed) read
328 const auto last_read
= peer_last_read_
.tv_sec
> 0 ?
329 peer_last_read_
: peer_last_write_
;
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;
344 HierarchyLogEntry::totalResponseTime(struct timeval
&responseTime
)
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);
352 responseTime
= totalResponseTime_
;
353 return responseTime
.tv_sec
>= 0 && responseTime
.tv_usec
>= 0;
357 accessLogRegisterWithCacheManager(void)
360 fvdbRegisterWithCacheManager();
369 accessLogRegisterWithCacheManager();
372 Log::TheConfig
.hasAdaptToken
= false;
375 Log::TheConfig
.hasIcapToken
= false;
378 for (log
= Config
.Log
.accesslogs
; log
; log
= log
->next
) {
379 if (log
->type
== Log::Format::CLF_NONE
)
382 log
->logfile
= logfileOpen(log
->filename
, log
->bufferSize
, log
->fatal
);
384 LogfileStatus
= LOG_ENABLE
;
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;
397 if (curr_token
->type
== Format::LFT_ICAP_TOTAL_TIME
) {
398 Log::TheConfig
.hasIcapToken
= true;
407 headerslog
= logfileOpen("/usr/local/squid/logs/headers.log", 512);
409 assert(NULL
!= headerslog
);
412 #if MULTICAST_MISS_STREAM
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
,
421 Config
.Addrs
.udp_incoming
,
422 Config
.mcast_miss
.port
,
424 "Multicast Miss Stream");
426 if (mcast_miss_fd
< 0)
427 fatal("Cannot open Multicast Miss Stream Socket");
429 debugs(46, DBG_IMPORTANT
, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd
);
431 mcastSetTtl(mcast_miss_fd
, Config
.mcast_miss
.ttl
);
433 if (strlen(Config
.mcast_miss
.encode_key
) < 16)
434 fatal("mcast_encode_key is too short, must be 16 characters");
443 fvdbRegisterWithCacheManager(void)
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);
451 fvdbCountVia(const SBuf
&headerValue
)
453 ++TheViaCounts
[headerValue
];
457 fvdbCountForwarded(const SBuf
&key
)
459 ++TheForwardedCounts
[key
];
463 fvdbDumpCounts(StoreEntry
&e
, const HeaderValueCounts
&counts
)
465 PackableStream
os(e
);
466 for (const auto &i
: counts
)
467 os
<< std::setw(9) << i
.second
<< ' ' << i
.first
<< "\n";
471 fvdbDumpVia(StoreEntry
* e
)
474 fvdbDumpCounts(*e
, TheViaCounts
);
478 fvdbDumpForwarded(StoreEntry
* e
)
481 fvdbDumpCounts(*e
, TheForwardedCounts
);
487 TheViaCounts
.clear();
488 TheForwardedCounts
.clear();
493 #if MULTICAST_MISS_STREAM
495 * From http://www.io.com/~paulhart/game/algorithms/tea.html
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.
503 mcast_encode(unsigned int *ibuf
, size_t isize
, const unsigned int *key
)
508 const unsigned int delta
= 0x9e3779b9;
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]);
516 for (i
= 0; i
< isize
; i
+= 2) {
518 z
= htonl(ibuf
[i
+ 1]);
521 for (n
= 32; n
; --n
) {
523 y
+= (z
<< 4) + (k0
^ z
) + (sum
^ (z
>> 5)) + k1
;
524 z
+= (y
<< 4) + (k2
^ y
) + (sum
^ (y
>> 5)) + k3
;
528 ibuf
[i
+ 1] = htonl(z
);
536 headersLog(int cs
, int pq
, const HttpRequestMethod
& method
, void *data
)
540 unsigned short magic
= 0;
541 unsigned char M
= (unsigned char) m
;
550 hmask
= rep
->header
.mask
;
552 if (rep
->cache_control
)
553 ccmask
= rep
->cache_control
->mask
;
559 hmask
= req
->header
.mask
;
561 if (req
->cache_control
)
562 ccmask
= req
->cache_control
->mask
;
573 magic
= htons(magic
);
574 ccmask
= htonl(ccmask
);
576 unsigned short S
= 0;
578 S
= static_cast<unsigned short>(rep
->sline
.status());
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));