debug.cc
Go to the documentation of this file.
1/*
2 * Copyright (C) 1996-2023 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 00 Debug Routines */
10
11#include "squid.h"
12#include "base/TextException.h"
13#include "debug/Stream.h"
14#include "fatal.h"
15#include "fd.h"
16#include "ipc/Kids.h"
17#include "time/gadgets.h"
18#include "util.h"
19
20#include <algorithm>
21#include <deque>
22#include <functional>
23#include <memory>
24#include <optional>
25
26char *Debug::debugOptions = nullptr;
27int Debug::override_X = 0;
28bool Debug::log_syslog = false;
30char *Debug::cache_log = nullptr;
31int Debug::rotateNumber = -1;
32
34using DebugRecordCount = uint64_t;
35
36class DebugModule;
37
39static DebugModule *Module_ = nullptr;
40
44static std::optional<int> ExplicitStderrLevel;
45
52static int DefaultStderrLevel = -1;
53
55static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
56
58static std::string ProcessLabel;
59
60static const char *debugLogTime(const timeval &);
61
62#if HAVE_SYSLOG
63#ifdef LOG_LOCAL4
64static int syslog_facility = 0;
65#endif
66#endif
67
68#if _SQUID_WINDOWS_
69extern LPCRITICAL_SECTION dbg_mutex;
70typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
71#endif
72
73static void ResetSections(const int level = DBG_IMPORTANT);
74
79static bool DidResetSections = false;
80
83{
84public:
87 DebugFile(DebugFile &&) = delete; // no copying or moving of any kind
88
90 void reset(FILE *newFile, const char *newName);
91
93 void clear() { reset(nullptr, nullptr); }
94
96 FILE *file() { return file_; }
97
98 char *name = nullptr;
99
100private:
101 friend void ResyncDebugLog(FILE *newFile);
102
103 FILE *file_ = nullptr;
104};
105
108{
109public:
110 DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &);
111
113 struct timeval timestamp;
115 int level;
117};
118
119// Avoid SBuf for CompiledDebugMessageBody:
120// * SBuf's own debugging may create a lot of reentrant debugging noise.
121// * Debug::Context::buf is an std::string-based STL ostream. Converting its
122// buf() result to a different kind of string may increase complexity/cost.
123// TODO: Consider switching to a simple fixed-size buffer and a matching stream!
125using CompiledDebugMessageBody = std::string;
126
129{
130public:
133
134 CompiledDebugMessage(const Header &, const Body &);
135
138};
139
140// We avoid PoolingAllocator for CompiledDebugMessages to minimize reentrant
141// debugging noise. This noise reduction has negligible performance overhead
142// because it only applied to early messages, and there are few of them.
144using CompiledDebugMessages = std::deque<CompiledDebugMessage>;
145
148{
149public:
150 using EarlyMessages = std::unique_ptr<CompiledDebugMessages>;
151
152 explicit DebugChannel(const char *aName);
153 virtual ~DebugChannel() = default;
154
155 // no copying or moving or any kind (for simplicity sake and to prevent accidental copies)
157
159 bool collectingEarlyMessages() const { return bool(earlyMessages); }
160
163
167
170 void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
171
172protected:
174 class Logger
175 {
176 public:
177 using difference_type = void;
178 using value_type = void;
179 using pointer = void;
180 using reference = void;
181 using iterator_category = std::output_iterator_tag;
182
183 explicit Logger(DebugChannel &ch): channel(ch) {}
184
186 {
187 if (Debug::Enabled(message.header.section, message.header.level))
188 channel.get().log(message.header, message.body);
189 return *this;
190 }
191
192 // These no-op operators are provided to satisfy LegacyOutputIterator requirements,
193 // as is customary for similar STL output iterators like std::ostream_iterator.
194 Logger &operator*() { return *this; }
195 Logger &operator++() { return *this; }
196 Logger &operator++(int) { return *this; }
197
198 private:
199 // wrap: output iterators must be CopyAssignable; raw references are not
200 std::reference_wrapper<DebugChannel> channel;
201 };
202
205 virtual bool shouldWrite(const DebugMessageHeader &) const = 0;
206
208 virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) = 0;
209
212
214 static void StopSavingAndLog(DebugChannel &, DebugChannel * = nullptr);
215
217 void writeToStream(FILE &, const DebugMessageHeader &, const CompiledDebugMessageBody &);
218
220 void noteWritten(const DebugMessageHeader &);
221
222protected:
223 const char * const name = nullptr;
224
227
230
235};
236
239{
240public:
241 CacheLogChannel(): DebugChannel("cache_log") {}
242
243protected:
244 /* DebugChannel API */
245 bool shouldWrite(const DebugMessageHeader &) const final;
246 void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
247};
248
251{
252public:
254
257
260
262 bool enabled(const int messageDebugLevel) const;
263
264protected:
265 /* DebugChannel API */
266 bool shouldWrite(const DebugMessageHeader &) const final;
267 void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
268
269private:
272};
273
276{
277public:
279
280 void markOpened() { opened = true; }
281
282protected:
283 /* DebugChannel API */
284 bool shouldWrite(const DebugMessageHeader &) const final;
285 void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
286
287private:
288 bool opened = false;
289};
290
296{
297public:
298 DebugModule();
299
300 // we provide debugging services for the entire duration of the program
301 ~DebugModule() = delete;
302
304 void prepareToDie();
305
308 void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
309
312 void useCacheLog();
313
316 void banCacheLogUse();
317
318public:
322};
323
329{
330public:
333
335 static bool Busy() { return LoggingConcurrencyLevel; }
336
337private:
340};
341
343
347
352
353FILE *
355 return TheLog.file() ? TheLog.file() : stderr;
356}
357
359static void
360ResetSections(const int level)
361{
362 DidResetSections = true;
363 for (auto &sectionLevel: Debug::Levels)
364 sectionLevel = level;
365}
366
368static void
369LabelThisProcess(const char * const name, const std::optional<int> id = std::optional<int>())
370{
371 assert(name);
372 assert(strlen(name));
373 std::stringstream os;
374 os << ' ' << name;
375 if (id.has_value()) {
376 assert(id.value() >= 0);
377 os << id.value();
378 }
379 ProcessLabel = os.str();
380}
381
382void
383Debug::NameThisHelper(const char * const name)
384{
385 LabelThisProcess(name);
386
387 if (const auto parentProcessDebugOptions = getenv("SQUID_DEBUG")) {
389 debugOptions = xstrdup(parentProcessDebugOptions);
390 }
391
392 // do not restrict helper (i.e. stderr) logging beyond debug_options
394
395 // helpers do not write to cache.log directly; instead, ipcCreate()
396 // diverts helper stderr output to cache.log of the parent process
398
399 SettleStderr();
400 SettleSyslog();
401
402 debugs(84, 2, "starting " << name << " with PID " << getpid());
403}
404
405void
406Debug::NameThisKid(const int kidIdentifier)
407{
408 // to reduce noise and for backward compatibility, do not label kid messages
409 // in non-SMP mode
410 if (kidIdentifier)
411 LabelThisProcess("kid", std::optional<int>(kidIdentifier));
412 else
413 ProcessLabel.clear(); // probably already empty
414}
415
416/* LoggingSectionGuard */
417
419{
421}
422
424{
425 if (--LoggingConcurrencyLevel == 0)
427}
428
429/* DebugModule */
430
431// Depending on DBG_CRITICAL activity and command line options, this code may
432// run as early as static initialization during program startup or as late as
433// the first debugs(DBG_CRITICAL) call from the main loop.
435{
436 // explicit initialization before any use by debugs() calls; see bug #2656
437 tzset();
438
439 (void)std::atexit(&Debug::PrepareToDie);
440
441 if (!DidResetSections)
443}
444
445void
447{
448 cacheLogChannel.log(header, body);
449 stderrChannel.log(header, body);
450 syslogChannel.log(header, body);
451}
452
453void
455{
456 const LoggingSectionGuard sectionGuard;
457
458 // Switch to stderr to improve our chances to log _early_ debugs(). However,
459 // use existing cache_log and/or stderr levels for post-open/close ones.
462
466
467 // Explicit last-resort call because we want to dump any pending messages
468 // (possibly including an assertion) even if another call, higher in the
469 // call stack, is currently in the sensitive section. Squid is dying, and
470 // that other caller (if any) will not get control back and, hence, will not
471 // trigger a Debug::LogWaitingForIdle() check. In most cases, we will log
472 // any pending messages successfully here. In the remaining few cases, we
473 // will lose them just like we would lose them without this call. The
474 // (small) risk here is that we might abort() or crash trying.
476
477 // Do not close/destroy channels: While the Debug module is not _guaranteed_
478 // to get control after prepareToDie(), debugs() calls are still very much
479 // _possible_, and we want to support/log them for as long as we can.
480}
481
482void
484{
485 assert(TheLog.file());
486 stderrChannel.stopCoveringForCacheLog(); // in case it was covering
487 cacheLogChannel.stopEarlyMessageCollection(); // in case it was collecting
488}
489
490void
492{
493 assert(!TheLog.file());
495}
496
498static
501{
502 if (!Module_) {
503 Module_ = new DebugModule();
504#if !HAVE_SYSLOG
505 // Optimization: Do not wait for others to tell us what we already know.
507#endif
508 }
509
510 return *Module_;
511}
512
513void
514ResyncDebugLog(FILE *newFile)
515{
516 TheLog.file_ = newFile;
517}
518
519/* DebugChannel */
520
521DebugChannel::DebugChannel(const char * const aName):
522 name(aName),
523 earlyMessages(new CompiledDebugMessages())
524{
525}
526
527void
529{
530 if (earlyMessages)
531 StopSavingAndLog(*this);
532 // else already stopped
533}
534
535void
537{
539 return;
540
541 if (!shouldWrite(header))
542 return saveMessage(header, body);
543
544 // We only save messages until we learn whether the channel is going to be
545 // used. We now know that it will be used. Also logs saved early messages
546 // (if they became eligible now) before lastWrittenRecordNumber blocks them.
548
549 write(header, body);
550}
551
552void
554{
555 auto &module = Module();
556 (void)module.cacheLogChannel.releaseEarlyMessages();
557 (void)module.stderrChannel.releaseEarlyMessages();
558 (void)module.syslogChannel.releaseEarlyMessages();
559}
560
561void
563{
565}
566
567void
569{
570 const LoggingSectionGuard sectionGuard;
571
572 assert(&channelA != channelBOrNil);
573 const auto asOrNil = channelA.releaseEarlyMessages();
574 const auto bsOrNil = channelBOrNil ? channelBOrNil->releaseEarlyMessages() : nullptr;
575 const auto &as = asOrNil ? *asOrNil : CompiledDebugMessages();
576 const auto &bs = bsOrNil ? *bsOrNil : CompiledDebugMessages();
577
578 const auto writtenEarlier = channelA.written;
579
580 std::merge(as.begin(), as.end(), bs.begin(), bs.end(), Logger(channelA),
581 [](const CompiledDebugMessage &mA, const CompiledDebugMessage &mB) {
582 return mA.header.recordNumber < mB.header.recordNumber;
583 });
584
585 const auto writtenNow = channelA.written - writtenEarlier;
586 if (const auto totalCount = as.size() + bs.size()) {
587 debugs(0, 5, "wrote " << writtenNow << " out of " << totalCount << '=' <<
588 as.size() << '+' << bs.size() << " early messages to " << channelA.name);
589 }
590}
591
592void
594{
595 if (!earlyMessages)
596 return; // we have stopped saving early messages
597
598 if (header.level > EarlyMessagesLevel)
599 return; // this message is not important enough to save
600
601 // Given small EarlyMessagesLevel, only a Squid bug can cause so many
602 // earlyMessages. Saving/dumping excessive messages correctly is not only
603 // difficult but is more likely to complicate triage than help: It is the
604 // first earlyMessages that are going to be the most valuable. Our assert()
605 // will dump them if at all possible.
606 assert(earlyMessages->size() < 1000);
607
608 earlyMessages->emplace_back(header, body);
609}
610
611void
612DebugChannel::writeToStream(FILE &destination, const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
613{
614 fprintf(&destination, "%s%s| %s\n",
615 debugLogTime(header.timestamp),
616 ProcessLabel.c_str(),
617 body.c_str());
618 noteWritten(header);
619}
620
621void
623{
624 ++written;
626}
627
628/* CacheLogChannel */
629
630bool
632{
633 return TheLog.file();
634}
635
636void
638{
639 writeToStream(*TheLog.file(), header, body);
640 fflush(TheLog.file());
641}
642
643/* StderrChannel */
644
645bool
646StderrChannel::enabled(const int level) const
647{
648 if (!stderr)
649 return false; // nowhere to write
650
651 if (ExplicitStderrLevel.has_value()) // explicit admin restrictions (-d)
652 return level <= ExplicitStderrLevel.value();
653
654 // whether the given level is allowed by emergency handling circumstances
655 // (coveringForCacheLog) or configuration aspects (e.g., -k or -z)
656 return coveringForCacheLog || level <= DefaultStderrLevel;
657}
658
659bool
661{
662 return enabled(header.level);
663}
664
665void
667{
668 writeToStream(*stderr, header, body);
669}
670
671void
673{
675 return;
676 coveringForCacheLog = true;
677
678 StopSavingAndLog(*this, &cacheLogChannel);
679}
680
681void
683{
685 return;
686
687 coveringForCacheLog = false;
688 debugs(0, DBG_IMPORTANT, "Resuming logging to cache_log");
689}
690
691void
693{
694 if (DefaultStderrLevel < maxDefault)
695 DefaultStderrLevel = maxDefault; // may set or increase
696 // else: somebody has already requested a more permissive maximum
697}
698
699void
700Debug::ResetStderrLevel(const int maxLevel)
701{
702 ExplicitStderrLevel = maxLevel; // may set, increase, or decrease
703}
704
705void
707{
708 auto &stderrChannel = Module().stderrChannel;
709
710 stderrChannel.stopEarlyMessageCollection();
711
712 if (override_X) {
713 // Some users might expect -X to force -d9. Tell them what is happening.
714 const auto outcome =
715 stderrChannel.enabled(DBG_DATA) ? "; stderr will see all messages":
716 stderrChannel.enabled(DBG_CRITICAL) ? "; stderr will not see some messages":
717 "; stderr will see no messages";
719 debugs(0, DBG_CRITICAL, "Using -X and -d" << ExplicitStderrLevel.value() << outcome);
720 else
721 debugs(0, DBG_CRITICAL, "Using -X without -d" << outcome);
722 }
723}
724
725bool
727{
729}
730
731/* DebugMessageHeader */
732
734 recordNumber(aRecordNumber),
735 section(context.section),
736 level(context.level),
737 forceAlert(context.forceAlert)
738{
739 (void)getCurrentTime(); // update current_time
741}
742
743/* CompiledDebugMessage */
744
746 header(aHeader),
747 body(aBody)
748{
749}
750
751/* DebugFile */
752
753void
754DebugFile::reset(FILE *newFile, const char *newName)
755{
756 // callers must use nullptr instead of the used-as-the-last-resort stderr
757 assert(newFile != stderr || !stderr);
758
759 if (file_) {
760 fd_close(fileno(file_));
761 fclose(file_);
762 }
763 file_ = newFile; // may be nil
764
765 if (file_)
767
768 xfree(name);
769 name = newName ? xstrdup(newName) : nullptr;
770
771 // all open files must have a name
772 // all cleared files must not have a name
773 assert(!file_ == !name);
774}
775
777void
779{
780#if _SQUID_WINDOWS_
781 /* Multiple WIN32 threads may call this simultaneously */
782
783 if (!dbg_mutex) {
784 HMODULE krnl_lib = GetModuleHandle("Kernel32");
785 PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount = nullptr;
786
787 if (krnl_lib)
788 InitializeCriticalSectionAndSpinCount =
789 (PFInitializeCriticalSectionAndSpinCount) GetProcAddress(krnl_lib,
790 "InitializeCriticalSectionAndSpinCount");
791
792 dbg_mutex = static_cast<CRITICAL_SECTION*>(xcalloc(1, sizeof(CRITICAL_SECTION)));
793
794 if (InitializeCriticalSectionAndSpinCount) {
795 /* let multiprocessor systems EnterCriticalSection() fast */
796
797 if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) {
798 if (const auto logFile = TheLog.file()) {
799 fprintf(logFile, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
800 fflush(logFile);
801 }
802
803 fprintf(stderr, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
804 abort();
805 } else
806 InitializeCriticalSection(dbg_mutex);
807 }
808 }
809
810 EnterCriticalSection(dbg_mutex);
811#endif
812
813 static DebugRecordCount LogMessageCalls = 0;
814 const DebugMessageHeader header(++LogMessageCalls, context);
815 Module().log(header, context.buf.str());
816
817#if _SQUID_WINDOWS_
818 LeaveCriticalSection(dbg_mutex);
819#endif
820}
821
822static void
823debugArg(const char *arg)
824{
825 int s = 0;
826 int l = 0;
827
828 if (!strncasecmp(arg, "rotate=", 7)) {
829 arg += 7;
830 Debug::rotateNumber = atoi(arg);
831 return;
832 } else if (!strncasecmp(arg, "ALL", 3)) {
833 s = -1;
834 arg += 4;
835 } else {
836 s = atoi(arg);
837 while (*arg && *arg++ != ',');
838 }
839
840 l = atoi(arg);
841 assert(s >= -1);
842
843 if (s >= MAX_DEBUG_SECTIONS)
844 s = MAX_DEBUG_SECTIONS-1;
845
846 if (l < 0)
847 l = 0;
848
849 if (l > 10)
850 l = 10;
851
852 if (s >= 0) {
853 Debug::Levels[s] = l;
854 return;
855 }
856
857 ResetSections(l);
858}
859
860static void
862{
864
865 // Bug 4423: ignore the stdio: logging module name if present
866 const char *logfilename;
867 if (strncmp(logfile, "stdio:",6) == 0)
868 logfilename = logfile + 6;
869 else
870 logfilename = logfile;
871
872 if (auto log = fopen(logfilename, "a+")) {
873#if _SQUID_WINDOWS_
874 setmode(fileno(log), O_TEXT);
875#endif
876 TheLog.reset(log, logfilename);
878 } else {
879 const auto xerrno = errno;
880 TheLog.clear();
882
883 // report the problem after banCacheLogUse() to improve our chances of
884 // reporting earlier debugs() messages (that cannot be written after us)
885 debugs(0, DBG_CRITICAL, "ERROR: Cannot open cache_log (" << logfilename << ") for writing;" <<
886 Debug::Extra << "fopen(3) error: " << xstrerr(xerrno));
887 }
888}
889
890#if HAVE_SYSLOG
891#ifdef LOG_LOCAL4
892
893static struct syslog_facility_name {
894 const char *name;
895 int facility;
896}
897
898syslog_facility_names[] = {
899
900#ifdef LOG_AUTH
901 {
902 "auth", LOG_AUTH
903 },
904#endif
905#ifdef LOG_AUTHPRIV
906 {
907 "authpriv", LOG_AUTHPRIV
908 },
909#endif
910#ifdef LOG_CRON
911 {
912 "cron", LOG_CRON
913 },
914#endif
915#ifdef LOG_DAEMON
916 {
917 "daemon", LOG_DAEMON
918 },
919#endif
920#ifdef LOG_FTP
921 {
922 "ftp", LOG_FTP
923 },
924#endif
925#ifdef LOG_KERN
926 {
927 "kern", LOG_KERN
928 },
929#endif
930#ifdef LOG_LPR
931 {
932 "lpr", LOG_LPR
933 },
934#endif
935#ifdef LOG_MAIL
936 {
937 "mail", LOG_MAIL
938 },
939#endif
940#ifdef LOG_NEWS
941 {
942 "news", LOG_NEWS
943 },
944#endif
945#ifdef LOG_SYSLOG
946 {
947 "syslog", LOG_SYSLOG
948 },
949#endif
950#ifdef LOG_USER
951 {
952 "user", LOG_USER
953 },
954#endif
955#ifdef LOG_UUCP
956 {
957 "uucp", LOG_UUCP
958 },
959#endif
960#ifdef LOG_LOCAL0
961 {
962 "local0", LOG_LOCAL0
963 },
964#endif
965#ifdef LOG_LOCAL1
966 {
967 "local1", LOG_LOCAL1
968 },
969#endif
970#ifdef LOG_LOCAL2
971 {
972 "local2", LOG_LOCAL2
973 },
974#endif
975#ifdef LOG_LOCAL3
976 {
977 "local3", LOG_LOCAL3
978 },
979#endif
980#ifdef LOG_LOCAL4
981 {
982 "local4", LOG_LOCAL4
983 },
984#endif
985#ifdef LOG_LOCAL5
986 {
987 "local5", LOG_LOCAL5
988 },
989#endif
990#ifdef LOG_LOCAL6
991 {
992 "local6", LOG_LOCAL6
993 },
994#endif
995#ifdef LOG_LOCAL7
996 {
997 "local7", LOG_LOCAL7
998 },
999#endif
1000 {
1001 nullptr, 0
1002 }
1003};
1004
1005#endif
1006
1007static void
1008_db_set_syslog(const char *facility)
1009{
1010 Debug::log_syslog = true;
1011
1012#ifdef LOG_LOCAL4
1013#ifdef LOG_DAEMON
1014
1015 syslog_facility = LOG_DAEMON;
1016#else
1017
1018 syslog_facility = LOG_LOCAL4;
1019#endif /* LOG_DAEMON */
1020
1021 if (facility) {
1022
1023 struct syslog_facility_name *n;
1024
1025 for (n = syslog_facility_names; n->name; ++n) {
1026 if (strcmp(n->name, facility) == 0) {
1027 syslog_facility = n->facility;
1028 return;
1029 }
1030 }
1031
1032 fprintf(stderr, "unknown syslog facility '%s'\n", facility);
1033 exit(EXIT_FAILURE);
1034 }
1035
1036#else
1037 if (facility)
1038 fprintf(stderr, "syslog facility type not supported on your system\n");
1039
1040#endif /* LOG_LOCAL4 */
1041}
1042
1043/* SyslogChannel */
1044
1045static int
1046SyslogPriority(const DebugMessageHeader &header)
1047{
1048 return header.forceAlert ? LOG_ALERT :
1049 (header.level == 0 ? LOG_WARNING : LOG_NOTICE);
1050}
1051
1052void
1054{
1055 syslog(SyslogPriority(header), "%s", body.c_str());
1056 noteWritten(header);
1057}
1058
1059#else
1060
1061void
1063{
1064 assert(!"unreachable code because opened, shouldWrite() are always false");
1065}
1066
1067#endif /* HAVE_SYSLOG */
1068
1069bool
1071{
1072 if (!opened)
1073 return false;
1074
1076 return header.forceAlert || header.level <= DBG_IMPORTANT;
1077}
1078
1079void
1080Debug::ConfigureSyslog(const char *facility)
1081{
1082#if HAVE_SYSLOG
1083 _db_set_syslog(facility);
1084#else
1085 (void)facility;
1086 // TODO: Throw.
1087 fatalf("Logging to syslog not available on this platform");
1088#endif
1089}
1090
1091void
1092Debug::parseOptions(char const *options)
1093{
1094 char *p = nullptr;
1095 char *s = nullptr;
1096
1097 if (override_X) {
1098 debugs(0, 9, "command-line -X overrides: " << options);
1099 return;
1100 }
1101
1102 ResetSections();
1103
1104 if (options) {
1105 p = xstrdup(options);
1106
1107 for (s = strtok(p, w_space); s; s = strtok(nullptr, w_space))
1108 debugArg(s);
1109
1110 xfree(p);
1111 }
1112}
1113
1114void
1116{
1119}
1120
1121void
1123{
1126}
1127
1128void
1130{
1131 if (TheLog.file()) {
1132 // UseCacheLog() was successful.
1134 TheLog.clear();
1135 } else {
1136 // UseCacheLog() was not called at all or failed to open cache_log.
1137 Module().banCacheLogUse(); // may already be banned
1138 }
1139}
1140
1141void
1143{
1144#if HAVE_SYSLOG && defined(LOG_LOCAL4)
1145
1146 if (Debug::log_syslog) {
1147 openlog(APP_SHORTNAME, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility);
1149 }
1150
1151#endif /* HAVE_SYSLOG */
1152
1154}
1155
1156void
1158{
1159 if (!TheLog.name)
1160 return;
1161
1162#ifdef S_ISREG
1163 struct stat sb;
1164 if (stat(TheLog.name, &sb) == 0)
1165 if (S_ISREG(sb.st_mode) == 0)
1166 return;
1167#endif
1168
1169 char from[MAXPATHLEN];
1170 from[0] = '\0';
1171
1172 char to[MAXPATHLEN];
1173 to[0] = '\0';
1174
1175 /*
1176 * NOTE: we cannot use xrename here without having it in a
1177 * separate file -- tools.c has too many dependencies to be
1178 * used everywhere debug.c is used.
1179 */
1180 /* Rotate numbers 0 through N up one */
1181 for (int i = Debug::rotateNumber; i > 1;) {
1182 --i;
1183 snprintf(from, MAXPATHLEN, "%s.%d", TheLog.name, i - 1);
1184 snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, i);
1185#if _SQUID_WINDOWS_
1186 remove
1187 (to);
1188#endif
1189 errno = 0;
1190 if (rename(from, to) == -1) {
1191 const auto saved_errno = errno;
1192 debugs(0, DBG_IMPORTANT, "ERROR: log rotation failed: " << xstrerr(saved_errno));
1193 }
1194 }
1195
1196 /* Rotate the current log to .0 */
1197 if (Debug::rotateNumber > 0) {
1198 // form file names before we may clear TheLog below
1199 snprintf(from, MAXPATHLEN, "%s", TheLog.name);
1200 snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, 0);
1201
1202#if _SQUID_WINDOWS_
1203 errno = 0;
1204 if (remove(to) == -1) {
1205 const auto saved_errno = errno;
1206 debugs(0, DBG_IMPORTANT, "ERROR: removal of log file " << to << " failed: " << xstrerr(saved_errno));
1207 }
1208 TheLog.clear(); // Windows cannot rename() open files
1209#endif
1210 errno = 0;
1211 if (rename(from, to) == -1) {
1212 const auto saved_errno = errno;
1213 debugs(0, DBG_IMPORTANT, "ERROR: renaming file " << from << " to "
1214 << to << "failed: " << xstrerr(saved_errno));
1215 }
1216 }
1217
1218 // Close (if we have not already) and reopen the log because
1219 // it may have been renamed "manually" before HUP'ing us.
1221}
1222
1223static const char *
1224debugLogTime(const timeval &t)
1225{
1226 static char buf[128]; // arbitrary size, big enough for the below timestamp strings.
1227 static time_t last_t = 0;
1228
1229 if (Debug::Level() > 1) {
1230 last_t = t.tv_sec;
1231 // 4 bytes smaller than buf to ensure .NNN catenation by snprintf()
1232 // is safe and works even if strftime() fills its buffer.
1233 char buf2[sizeof(buf)-4];
1234 const auto tm = localtime(&last_t);
1235 strftime(buf2, sizeof(buf2), "%Y/%m/%d %H:%M:%S", tm);
1236 buf2[sizeof(buf2)-1] = '\0';
1237 const auto sz = snprintf(buf, sizeof(buf), "%s.%03d", buf2, static_cast<int>(t.tv_usec / 1000));
1238 assert(0 < sz && sz < static_cast<int>(sizeof(buf)));
1239 // force buf reset for subsequent level-0/1 messages that should have no milliseconds
1240 last_t = 0;
1241 } else if (t.tv_sec != last_t) {
1242 last_t = t.tv_sec;
1243 const auto tm = localtime(&last_t);
1244 const int sz = strftime(buf, sizeof(buf), "%Y/%m/%d %H:%M:%S", tm);
1245 assert(0 < sz && sz <= static_cast<int>(sizeof(buf)));
1246 }
1247
1248 buf[sizeof(buf)-1] = '\0';
1249 return buf;
1250}
1251
1254static auto Asserting_ = false;
1255
1256void
1257xassert(const char *msg, const char *file, int line)
1258{
1259 // if the non-trivial code below has itself asserted, then simplify instead
1260 // of running out of stack and complicating triage
1261 if (Asserting_)
1262 abort();
1263
1264 Asserting_ = true;
1265
1266 debugs(0, DBG_CRITICAL, "FATAL: assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
1267
1269 abort();
1270}
1271
1273
1274Debug::Context::Context(const int aSection, const int aLevel):
1275 section(aSection),
1276 level(aLevel),
1277 sectionLevel(Levels[aSection]),
1278 upper(Current),
1279 forceAlert(false),
1280 waitingForIdle(false)
1281{
1283}
1284
1286void
1287Debug::Context::rewind(const int aSection, const int aLevel)
1288{
1289 section = aSection;
1290 level = aLevel;
1291 sectionLevel = Levels[aSection];
1292 assert(upper == Current);
1293 assert(!waitingForIdle);
1294
1295 buf.str(CompiledDebugMessageBody());
1296 buf.clear();
1297 FormatStream(buf);
1298}
1299
1301void
1302Debug::FormatStream(std::ostream &buf)
1303{
1304 const static std::ostringstream cleanStream;
1305 buf.flags(cleanStream.flags() | std::ios::fixed);
1306 buf.width(cleanStream.width());
1307 buf.precision(2);
1308 buf.fill(' ');
1309 // If this is not enough, use copyfmt(cleanStream) which is ~10% slower.
1310}
1311
1312std::ostream &
1313Debug::Extra(std::ostream &os)
1314{
1315 // Prevent previous line formats bleeding onto this line: Previous line code
1316 // may not even be aware of some detailing code automatically adding extras.
1317 FormatStream(os);
1318
1319 os << "\n ";
1320 return os;
1321}
1322
1323void
1325{
1326 if (!WaitingForIdle)
1327 return; // do not lock in vain because unlocking would calls us
1328
1329 const LoggingSectionGuard sectionGuard;
1330 while (const auto current = WaitingForIdle) {
1331 assert(current->waitingForIdle);
1332 LogMessage(*current);
1333 WaitingForIdle = current->upper;
1334 delete current;
1335 }
1336}
1337
1338std::ostringstream &
1339Debug::Start(const int section, const int level)
1340{
1341 Context *future = nullptr;
1342
1344 // a very rare reentrant debugs() call that originated during Finish() and such
1345 future = new Context(section, level);
1346 future->waitingForIdle = true;
1347 } else if (Current) {
1348 // a rare reentrant debugs() call that originated between Start() and Finish()
1349 future = new Context(section, level);
1350 } else {
1351 // Optimization: Nearly all debugs() calls get here; avoid allocations
1352 static Context *topContext = new Context(1, 1);
1353 topContext->rewind(section, level);
1354 future = topContext;
1355 }
1356
1357 Current = future;
1358
1359 return future->buf;
1360}
1361
1362void
1364{
1365 const LoggingSectionGuard sectionGuard;
1366
1367 // TODO: #include "base/CodeContext.h" instead if doing so works well.
1368 extern std::ostream &CurrentCodeContextDetail(std::ostream &os);
1369 if (Current->level <= DBG_IMPORTANT)
1371
1372 if (Current->waitingForIdle) {
1373 const auto past = Current;
1374 Current = past->upper;
1375 past->upper = nullptr;
1376 // do not delete `past` because we store it in WaitingForIdle below
1377
1378 // waitingForIdle messages are queued here instead of Start() because
1379 // their correct order is determined by the Finish() call timing/order.
1380 // Linear search, but this list ought to be very short (usually empty).
1381 auto *last = &WaitingForIdle;
1382 while (*last)
1383 last = &(*last)->upper;
1384 *last = past;
1385
1386 return;
1387 }
1388
1390 Current->forceAlert = false;
1391
1392 Context *past = Current;
1393 Current = past->upper;
1394 if (Current)
1395 delete past;
1396 // else it was a static topContext from Debug::Start()
1397}
1398
1399void
1401{
1402 // the ForceAlert(ostream) manipulator should only be used inside debugs()
1403 if (Current)
1404 Current->forceAlert = true;
1405}
1406
1407std::ostream&
1408ForceAlert(std::ostream& s)
1409{
1411 return s;
1412}
1413
std::ostream & CurrentCodeContextDetail(std::ostream &os)
Definition: CodeContext.cc:96
SQUIDCEXTERN LPCRITICAL_SECTION dbg_mutex
Definition: WinSvc.cc:48
void log(char *format,...)
#define assert(EX)
Definition: assert.h:17
DebugChannel managing messages destined for the configured cache_log file.
Definition: debug.cc:239
void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final
write the corresponding debugs() message into the channel
Definition: debug.cc:637
bool shouldWrite(const DebugMessageHeader &) const final
Definition: debug.cc:631
a fully processed debugs(), ready to be logged
Definition: debug.cc:129
CompiledDebugMessage(const Header &, const Body &)
Definition: debug.cc:745
CompiledDebugMessageBody Body
Definition: debug.cc:132
Header header
debugs() meta-information; reflected in log line prefix
Definition: debug.cc:136
Body body
the log line after the prefix (without the newline)
Definition: debug.cc:137
output iterator for writing CompiledDebugMessages to a given channel
Definition: debug.cc:175
Logger(DebugChannel &ch)
Definition: debug.cc:183
std::reference_wrapper< DebugChannel > channel
output destination
Definition: debug.cc:200
Logger & operator++()
Definition: debug.cc:195
Logger & operator=(const CompiledDebugMessage &message)
Definition: debug.cc:185
Logger & operator++(int)
Definition: debug.cc:196
std::output_iterator_tag iterator_category
Definition: debug.cc:181
Logger & operator*()
Definition: debug.cc:194
a receiver of debugs() messages (e.g., stderr or cache.log)
Definition: debug.cc:148
DebugChannel(DebugChannel &&)=delete
DebugRecordCount written
the number of messages sent to the underlying channel so far
Definition: debug.cc:226
void saveMessage(const DebugMessageHeader &, const CompiledDebugMessageBody &)
stores the given early message (if possible) or forgets it (otherwise)
Definition: debug.cc:593
static void StopSavingAndLog(DebugChannel &, DebugChannel *=nullptr)
stop saving and log() any "early" messages, in recordNumber order
Definition: debug.cc:568
void noteWritten(const DebugMessageHeader &)
reacts to a written a debugs() message
Definition: debug.cc:622
void writeToStream(FILE &, const DebugMessageHeader &, const CompiledDebugMessageBody &)
Formats a validated debugs() record and writes it to the given FILE.
Definition: debug.cc:612
virtual ~DebugChannel()=default
EarlyMessages releaseEarlyMessages()
Definition: debug.cc:166
void log(const DebugMessageHeader &, const CompiledDebugMessageBody &)
Definition: debug.cc:536
std::unique_ptr< CompiledDebugMessages > EarlyMessages
Definition: debug.cc:150
void stopEarlyMessageCollection()
end early message buffering, logging any saved messages
Definition: debug.cc:528
bool collectingEarlyMessages() const
whether we are still expecting (and buffering) early messages
Definition: debug.cc:159
DebugChannel(const char *aName)
Definition: debug.cc:521
const char *const name
unique channel label for debugging
Definition: debug.cc:223
virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &)=0
write the corresponding debugs() message into the channel
EarlyMessages earlyMessages
Definition: debug.cc:234
DebugRecordCount lastWrittenRecordNumber
DebugMessageHeader::recordNumber of the last message we wrote.
Definition: debug.cc:229
virtual bool shouldWrite(const DebugMessageHeader &) const =0
a named FILE with very-early/late usage safety mechanisms
Definition: debug.cc:83
friend void ResyncDebugLog(FILE *newFile)
a hack for low-level file descriptor manipulations in ipcCreate()
Definition: debug.cc:514
char * name
Definition: debug.cc:98
FILE * file()
an opened cache_log stream or nil
Definition: debug.cc:96
~DebugFile()
Definition: debug.cc:86
DebugFile(DebugFile &&)=delete
void clear()
go back to the initial state
Definition: debug.cc:93
FILE * file_
opened "real" file or nil; never stderr
Definition: debug.cc:103
void reset(FILE *newFile, const char *newName)
switches to the new pair, absorbing FILE and duping the name
Definition: debug.cc:754
DebugFile()
Definition: debug.cc:85
meta-information of a Finish()ed debugs() message
Definition: debug.cc:108
DebugRecordCount recordNumber
LogMessage() calls before this message.
Definition: debug.cc:112
int section
debugs() section
Definition: debug.cc:114
int level
debugs() level
Definition: debug.cc:115
bool forceAlert
debugs() forceAlert flag
Definition: debug.cc:116
DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &)
Definition: debug.cc:733
struct timeval timestamp
approximate debugs() call time
Definition: debug.cc:113
~DebugModule()=delete
DebugModule()
Definition: debug.cc:434
SyslogChannel syslogChannel
Definition: debug.cc:321
CacheLogChannel cacheLogChannel
Definition: debug.cc:319
void banCacheLogUse()
Definition: debug.cc:491
StderrChannel stderrChannel
Definition: debug.cc:320
void log(const DebugMessageHeader &, const CompiledDebugMessageBody &)
Definition: debug.cc:446
void useCacheLog()
Definition: debug.cc:483
void prepareToDie()
Definition: debug.cc:454
meta-information for debugs() or a similar debugging call
Definition: Stream.h:52
bool waitingForIdle
Definition: Stream.h:71
Context * upper
previous or parent record in nested debugging calls
Definition: Stream.h:65
std::ostringstream buf
debugs() output sink
Definition: Stream.h:66
int level
minimum debugging level required by the debugs() call
Definition: Stream.h:57
bool forceAlert
the current debugs() will be a syslog ALERT
Definition: Stream.h:67
void rewind(const int aSection, const int aLevel)
Optimization: avoids new Context creation for every debugs().
Definition: debug.cc:1287
Context(const int aSectionLevel, const int aLevel)
Definition: debug.cc:1274
static void ResetStderrLevel(int maxLevel)
Definition: debug.cc:700
static bool StderrEnabled()
Definition: debug.cc:726
static bool log_syslog
Definition: Stream.h:85
static void parseOptions(char const *)
Definition: debug.cc:1092
static void PrepareToDie()
Definition: debug.cc:562
static void ForgetSaved()
silently erases saved early debugs() messages (if any)
Definition: debug.cc:553
static bool Enabled(const int section, const int level)
whether debugging the given section and the given level produces output
Definition: Stream.h:75
static Context * Current
deepest active context; nil outside debugs()
Definition: Stream.h:176
static std::ostream & Extra(std::ostream &)
Definition: debug.cc:1313
static void NameThisKid(int kidIdentifier)
Definition: debug.cc:406
static void LogMessage(const Context &)
broadcasts debugs() message to the logging channels
Definition: debug.cc:778
static int override_X
Definition: Stream.h:84
static void SettleSyslog()
Definition: debug.cc:1142
static int Levels[MAX_DEBUG_SECTIONS]
Definition: Stream.h:83
static void Finish()
logs output buffer created in Start() and closes debugging context
Definition: debug.cc:1363
static void NameThisHelper(const char *name)
Definition: debug.cc:383
static char * debugOptions
Definition: Stream.h:80
static void UseCacheLog()
Definition: debug.cc:1122
static char * cache_log
Definition: Stream.h:81
static void FormatStream(std::ostream &)
configures default formatting for the debugging stream
Definition: debug.cc:1302
static std::ostringstream & Start(const int section, const int level)
opens debugging context and returns output buffer
Definition: debug.cc:1339
static void BanCacheLogUse()
Definition: debug.cc:1115
static void ConfigureSyslog(const char *facility)
enables logging to syslog (using the specified facility, when not nil)
Definition: debug.cc:1080
static void StopCacheLogUse()
Definition: debug.cc:1129
static int Level()
minimum level required by the current debugs() call
Definition: Stream.h:100
static int rotateNumber
Definition: Stream.h:82
static void EnsureDefaultStderrLevel(int maxDefault)
Definition: debug.cc:692
static void SettleStderr()
Definition: debug.cc:706
static void LogWaitingForIdle()
Logs messages of Finish()ed debugs() calls that were queued earlier.
Definition: debug.cc:1324
static void ForceAlert()
configures the active debugging context to write syslog ALERT
Definition: debug.cc:1400
static bool Busy()
whether new debugs() messages must be queued
Definition: debug.cc:335
static size_t LoggingConcurrencyLevel
the current number of protected callers
Definition: debug.cc:339
DebugChannel managing messages destined for "standard error stream" (stderr)
Definition: debug.cc:251
bool shouldWrite(const DebugMessageHeader &) const final
Definition: debug.cc:660
bool enabled(const int messageDebugLevel) const
Definition: debug.cc:646
void takeOver(CacheLogChannel &)
start to take care of past/saved and future cacheLovirtual gChannel messages
Definition: debug.cc:672
void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final
write the corresponding debugs() message into the channel
Definition: debug.cc:666
void stopCoveringForCacheLog()
stop providing a cache_log replacement (if we were providing it)
Definition: debug.cc:682
StderrChannel()
Definition: debug.cc:253
bool coveringForCacheLog
whether we are the last resort for logging debugs() messages
Definition: debug.cc:271
syslog DebugChannel
Definition: debug.cc:276
bool shouldWrite(const DebugMessageHeader &) const final
Definition: debug.cc:1070
bool opened
whether openlog() was called
Definition: debug.cc:288
void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final
write the corresponding debugs() message into the channel
Definition: debug.cc:1062
SyslogChannel()
Definition: debug.cc:278
void markOpened()
Definition: debug.cc:280
void fd_open(const int fd, unsigned int, const char *description)
Definition: minimal.cc:14
void fd_close(const int fd)
Definition: minimal.cc:20
#define w_space
#define DBG_DATA
Definition: Stream.h:40
#define MAX_DEBUG_SECTIONS
Definition: Stream.h:34
#define DBG_IMPORTANT
Definition: Stream.h:38
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Stream.h:194
#define DBG_CRITICAL
Definition: Stream.h:37
#define O_TEXT
Definition: defines.h:133
@ FD_LOG
Definition: enums.h:14
static FILE * logfile
void fatalf(const char *fmt,...)
Definition: fatal.cc:68
#define xfree
#define xstrdup
static char last
Definition: parse.c:451
static struct stat sb
Definition: squidclient.cc:71
FILE * DebugStream()
Definition: debug.cc:354
void ResyncDebugLog(FILE *newFile)
a hack for low-level file descriptor manipulations in ipcCreate()
Definition: debug.cc:514
static DebugModule & Module()
safe access to the debugging module
Definition: debug.cc:500
static std::optional< int > ExplicitStderrLevel
Definition: debug.cc:44
std::deque< CompiledDebugMessage > CompiledDebugMessages
debugs() messages captured in LogMessage() call order
Definition: debug.cc:144
uint64_t DebugRecordCount
a counter related to the number of debugs() calls
Definition: debug.cc:34
static DebugModule * Module_
Debugging module singleton.
Definition: debug.cc:39
static auto Asserting_
Definition: debug.cc:1254
static void LabelThisProcess(const char *const name, const std::optional< int > id=std::optional< int >())
optimization: formats ProcessLabel once for frequent debugs() reuse
Definition: debug.cc:369
static Debug::Context * WaitingForIdle
Definition: debug.cc:346
static const char * debugLogTime(const timeval &)
Definition: debug.cc:1224
static void debugOpenLog(const char *logfile)
Definition: debug.cc:861
static int DefaultStderrLevel
Definition: debug.cc:52
void _db_rotate_log(void)
Definition: debug.cc:1157
static std::string ProcessLabel
pre-formatted name of the current process for debugs() messages (or empty)
Definition: debug.cc:58
void xassert(const char *msg, const char *file, int line)
Definition: debug.cc:1257
static bool DidResetSections
Definition: debug.cc:79
static DebugFile TheLog
Definition: debug.cc:351
static void ResetSections(const int level=DBG_IMPORTANT)
used for the side effect: fills Debug::Levels with the given level
Definition: debug.cc:360
static constexpr int EarlyMessagesLevel
early debugs() with higher level are not buffered and, hence, may be lost
Definition: debug.cc:55
std::string CompiledDebugMessageBody
The processed "content" (i.e. the last parameter) part of a debugs() call.
Definition: debug.cc:125
static void debugArg(const char *arg)
Definition: debug.cc:823
#define BOOL
Definition: std-includes.h:38
#define MAXPATHLEN
Definition: stdio.h:62
time_t getCurrentTime() STUB_RETVAL(0) int tvSubUsec(struct timeval
struct timeval current_time
the current UNIX time in timeval {seconds, microseconds} format
Definition: gadgets.cc:17
#define APP_SHORTNAME
Definition: version.h:22
void * xcalloc(size_t n, size_t sz)
Definition: xalloc.cc:71
const char * xstrerr(int error)
Definition: xstrerror.cc:83

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors