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