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 "fd.h"
15#include "ipc/Kids.h"
16#include "time/gadgets.h"
17#include "util.h"
18
19#include <algorithm>
20#include <deque>
21#include <functional>
22#include <memory>
23#include <optional>
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
43static std::optional<int> ExplicitStderrLevel;
44
51static int DefaultStderrLevel = -1;
52
54static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
55
57static std::string ProcessLabel;
58
59static const char *debugLogTime(const timeval &);
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 struct timeval 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 bool shouldWrite(const DebugMessageHeader &) const final;
245 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 bool shouldWrite(const DebugMessageHeader &) const final;
266 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 bool shouldWrite(const DebugMessageHeader &) const final;
284 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 std::optional<int> id = std::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", std::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 section(context.section),
735 level(context.level),
736 forceAlert(context.forceAlert)
737{
738 (void)getCurrentTime(); // update current_time
740}
741
742/* CompiledDebugMessage */
743
745 header(aHeader),
746 body(aBody)
747{
748}
749
750/* DebugFile */
751
752void
753DebugFile::reset(FILE *newFile, const char *newName)
754{
755 // callers must use nullptr instead of the used-as-the-last-resort stderr
756 assert(newFile != stderr || !stderr);
757
758 if (file_) {
759 fd_close(fileno(file_));
760 fclose(file_);
761 }
762 file_ = newFile; // may be nil
763
764 if (file_)
766
767 xfree(name);
768 name = newName ? xstrdup(newName) : nullptr;
769
770 // all open files must have a name
771 // all cleared files must not have a name
772 assert(!file_ == !name);
773}
774
776void
778{
779#if _SQUID_WINDOWS_
780 /* Multiple WIN32 threads may call this simultaneously */
781
782 if (!dbg_mutex) {
783 HMODULE krnl_lib = GetModuleHandle("Kernel32");
784 PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount = NULL;
785
786 if (krnl_lib)
787 InitializeCriticalSectionAndSpinCount =
788 (PFInitializeCriticalSectionAndSpinCount) GetProcAddress(krnl_lib,
789 "InitializeCriticalSectionAndSpinCount");
790
791 dbg_mutex = static_cast<CRITICAL_SECTION*>(xcalloc(1, sizeof(CRITICAL_SECTION)));
792
793 if (InitializeCriticalSectionAndSpinCount) {
794 /* let multiprocessor systems EnterCriticalSection() fast */
795
796 if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) {
797 if (const auto logFile = TheLog.file()) {
798 fprintf(logFile, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
799 fflush(logFile);
800 }
801
802 fprintf(stderr, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
803 abort();
804 } else
805 InitializeCriticalSection(dbg_mutex);
806 }
807 }
808
809 EnterCriticalSection(dbg_mutex);
810#endif
811
812 static DebugRecordCount LogMessageCalls = 0;
813 const DebugMessageHeader header(++LogMessageCalls, context);
814 Module().log(header, context.buf.str());
815
816#if _SQUID_WINDOWS_
817 LeaveCriticalSection(dbg_mutex);
818#endif
819}
820
821static void
822debugArg(const char *arg)
823{
824 int s = 0;
825 int l = 0;
826
827 if (!strncasecmp(arg, "rotate=", 7)) {
828 arg += 7;
829 Debug::rotateNumber = atoi(arg);
830 return;
831 } else if (!strncasecmp(arg, "ALL", 3)) {
832 s = -1;
833 arg += 4;
834 } else {
835 s = atoi(arg);
836 while (*arg && *arg++ != ',');
837 }
838
839 l = atoi(arg);
840 assert(s >= -1);
841
842 if (s >= MAX_DEBUG_SECTIONS)
843 s = MAX_DEBUG_SECTIONS-1;
844
845 if (l < 0)
846 l = 0;
847
848 if (l > 10)
849 l = 10;
850
851 if (s >= 0) {
852 Debug::Levels[s] = l;
853 return;
854 }
855
856 ResetSections(l);
857}
858
859static void
861{
863
864 // Bug 4423: ignore the stdio: logging module name if present
865 const char *logfilename;
866 if (strncmp(logfile, "stdio:",6) == 0)
867 logfilename = logfile + 6;
868 else
869 logfilename = logfile;
870
871 if (auto log = fopen(logfilename, "a+")) {
872#if _SQUID_WINDOWS_
873 setmode(fileno(log), O_TEXT);
874#endif
875 TheLog.reset(log, logfilename);
877 } else {
878 const auto xerrno = errno;
879 TheLog.clear();
881
882 // report the problem after banCacheLogUse() to improve our chances of
883 // reporting earlier debugs() messages (that cannot be written after us)
884 debugs(0, DBG_CRITICAL, "ERROR: Cannot open cache_log (" << logfilename << ") for writing;" <<
885 Debug::Extra << "fopen(3) error: " << xstrerr(xerrno));
886 }
887}
888
889#if HAVE_SYSLOG
890#ifdef LOG_LOCAL4
891
892static struct syslog_facility_name {
893 const char *name;
894 int facility;
895}
896
897syslog_facility_names[] = {
898
899#ifdef LOG_AUTH
900 {
901 "auth", LOG_AUTH
902 },
903#endif
904#ifdef LOG_AUTHPRIV
905 {
906 "authpriv", LOG_AUTHPRIV
907 },
908#endif
909#ifdef LOG_CRON
910 {
911 "cron", LOG_CRON
912 },
913#endif
914#ifdef LOG_DAEMON
915 {
916 "daemon", LOG_DAEMON
917 },
918#endif
919#ifdef LOG_FTP
920 {
921 "ftp", LOG_FTP
922 },
923#endif
924#ifdef LOG_KERN
925 {
926 "kern", LOG_KERN
927 },
928#endif
929#ifdef LOG_LPR
930 {
931 "lpr", LOG_LPR
932 },
933#endif
934#ifdef LOG_MAIL
935 {
936 "mail", LOG_MAIL
937 },
938#endif
939#ifdef LOG_NEWS
940 {
941 "news", LOG_NEWS
942 },
943#endif
944#ifdef LOG_SYSLOG
945 {
946 "syslog", LOG_SYSLOG
947 },
948#endif
949#ifdef LOG_USER
950 {
951 "user", LOG_USER
952 },
953#endif
954#ifdef LOG_UUCP
955 {
956 "uucp", LOG_UUCP
957 },
958#endif
959#ifdef LOG_LOCAL0
960 {
961 "local0", LOG_LOCAL0
962 },
963#endif
964#ifdef LOG_LOCAL1
965 {
966 "local1", LOG_LOCAL1
967 },
968#endif
969#ifdef LOG_LOCAL2
970 {
971 "local2", LOG_LOCAL2
972 },
973#endif
974#ifdef LOG_LOCAL3
975 {
976 "local3", LOG_LOCAL3
977 },
978#endif
979#ifdef LOG_LOCAL4
980 {
981 "local4", LOG_LOCAL4
982 },
983#endif
984#ifdef LOG_LOCAL5
985 {
986 "local5", LOG_LOCAL5
987 },
988#endif
989#ifdef LOG_LOCAL6
990 {
991 "local6", LOG_LOCAL6
992 },
993#endif
994#ifdef LOG_LOCAL7
995 {
996 "local7", LOG_LOCAL7
997 },
998#endif
999 {
1000 nullptr, 0
1001 }
1002};
1003
1004#endif
1005
1006static void
1007_db_set_syslog(const char *facility)
1008{
1009 Debug::log_syslog = true;
1010
1011#ifdef LOG_LOCAL4
1012#ifdef LOG_DAEMON
1013
1014 syslog_facility = LOG_DAEMON;
1015#else
1016
1017 syslog_facility = LOG_LOCAL4;
1018#endif /* LOG_DAEMON */
1019
1020 if (facility) {
1021
1022 struct syslog_facility_name *n;
1023
1024 for (n = syslog_facility_names; n->name; ++n) {
1025 if (strcmp(n->name, facility) == 0) {
1026 syslog_facility = n->facility;
1027 return;
1028 }
1029 }
1030
1031 fprintf(stderr, "unknown syslog facility '%s'\n", facility);
1032 exit(EXIT_FAILURE);
1033 }
1034
1035#else
1036 if (facility)
1037 fprintf(stderr, "syslog facility type not supported on your system\n");
1038
1039#endif /* LOG_LOCAL4 */
1040}
1041
1042/* SyslogChannel */
1043
1044static int
1045SyslogPriority(const DebugMessageHeader &header)
1046{
1047 return header.forceAlert ? LOG_ALERT :
1048 (header.level == 0 ? LOG_WARNING : LOG_NOTICE);
1049}
1050
1051void
1053{
1054 syslog(SyslogPriority(header), "%s", body.c_str());
1055 noteWritten(header);
1056}
1057
1058#else
1059
1060void
1062{
1063 assert(!"unreachable code because opened, shouldWrite() are always false");
1064}
1065
1066#endif /* HAVE_SYSLOG */
1067
1068bool
1070{
1071 if (!opened)
1072 return false;
1073
1075 return header.forceAlert || header.level <= DBG_IMPORTANT;
1076}
1077
1078void
1079Debug::ConfigureSyslog(const char *facility)
1080{
1081#if HAVE_SYSLOG
1082 _db_set_syslog(facility);
1083#else
1084 (void)facility;
1085 // TODO: Throw.
1086 fatalf("Logging to syslog not available on this platform");
1087#endif
1088}
1089
1090void
1091Debug::parseOptions(char const *options)
1092{
1093 char *p = nullptr;
1094 char *s = nullptr;
1095
1096 if (override_X) {
1097 debugs(0, 9, "command-line -X overrides: " << options);
1098 return;
1099 }
1100
1101 ResetSections();
1102
1103 if (options) {
1104 p = xstrdup(options);
1105
1106 for (s = strtok(p, w_space); s; s = strtok(nullptr, w_space))
1107 debugArg(s);
1108
1109 xfree(p);
1110 }
1111}
1112
1113void
1115{
1118}
1119
1120void
1122{
1125}
1126
1127void
1129{
1130 if (TheLog.file()) {
1131 // UseCacheLog() was successful.
1133 TheLog.clear();
1134 } else {
1135 // UseCacheLog() was not called at all or failed to open cache_log.
1136 Module().banCacheLogUse(); // may already be banned
1137 }
1138}
1139
1140void
1142{
1143#if HAVE_SYSLOG && defined(LOG_LOCAL4)
1144
1145 if (Debug::log_syslog) {
1146 openlog(APP_SHORTNAME, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility);
1148 }
1149
1150#endif /* HAVE_SYSLOG */
1151
1153}
1154
1155void
1157{
1158 if (!TheLog.name)
1159 return;
1160
1161#ifdef S_ISREG
1162 struct stat sb;
1163 if (stat(TheLog.name, &sb) == 0)
1164 if (S_ISREG(sb.st_mode) == 0)
1165 return;
1166#endif
1167
1168 char from[MAXPATHLEN];
1169 from[0] = '\0';
1170
1171 char to[MAXPATHLEN];
1172 to[0] = '\0';
1173
1174 /*
1175 * NOTE: we cannot use xrename here without having it in a
1176 * separate file -- tools.c has too many dependencies to be
1177 * used everywhere debug.c is used.
1178 */
1179 /* Rotate numbers 0 through N up one */
1180 for (int i = Debug::rotateNumber; i > 1;) {
1181 --i;
1182 snprintf(from, MAXPATHLEN, "%s.%d", TheLog.name, i - 1);
1183 snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, i);
1184#if _SQUID_WINDOWS_
1185 remove
1186 (to);
1187#endif
1188 errno = 0;
1189 if (rename(from, to) == -1) {
1190 const auto saved_errno = errno;
1191 debugs(0, DBG_IMPORTANT, "ERROR: log rotation failed: " << xstrerr(saved_errno));
1192 }
1193 }
1194
1195 /* Rotate the current log to .0 */
1196 if (Debug::rotateNumber > 0) {
1197 // form file names before we may clear TheLog below
1198 snprintf(from, MAXPATHLEN, "%s", TheLog.name);
1199 snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, 0);
1200
1201#if _SQUID_WINDOWS_
1202 errno = 0;
1203 if (remove(to) == -1) {
1204 const auto saved_errno = errno;
1205 debugs(0, DBG_IMPORTANT, "ERROR: removal of log file " << to << " failed: " << xstrerr(saved_errno));
1206 }
1207 TheLog.clear(); // Windows cannot rename() open files
1208#endif
1209 errno = 0;
1210 if (rename(from, to) == -1) {
1211 const auto saved_errno = errno;
1212 debugs(0, DBG_IMPORTANT, "ERROR: renaming file " << from << " to "
1213 << to << "failed: " << xstrerr(saved_errno));
1214 }
1215 }
1216
1217 // Close (if we have not already) and reopen the log because
1218 // it may have been renamed "manually" before HUP'ing us.
1220}
1221
1222static const char *
1223debugLogTime(const timeval &t)
1224{
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 const auto tm = localtime(&t.tv_sec);
1233 strftime(buf2, sizeof(buf2), "%Y/%m/%d %H:%M:%S", tm);
1234 buf2[sizeof(buf2)-1] = '\0';
1235 const auto sz = snprintf(buf, sizeof(buf), "%s.%03d", buf2, static_cast<int>(t.tv_usec / 1000));
1236 assert(0 < sz && sz < static_cast<int>(sizeof(buf)));
1237 // force buf reset for subsequent level-0/1 messages that should have no milliseconds
1238 last_t = 0;
1239 } else if (t.tv_sec != last_t) {
1240 const auto tm = localtime(&t.tv_sec);
1241 const int sz = strftime(buf, sizeof(buf), "%Y/%m/%d %H:%M:%S", tm);
1242 assert(0 < sz && sz <= static_cast<int>(sizeof(buf)));
1243 last_t = t.tv_sec;
1244 }
1245
1246 buf[sizeof(buf)-1] = '\0';
1247 return buf;
1248}
1249
1252static auto Asserting_ = false;
1253
1254void
1255xassert(const char *msg, const char *file, int line)
1256{
1257 // if the non-trivial code below has itself asserted, then simplify instead
1258 // of running out of stack and complicating triage
1259 if (Asserting_)
1260 abort();
1261
1262 Asserting_ = true;
1263
1264 debugs(0, DBG_CRITICAL, "FATAL: assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
1265
1267 abort();
1268}
1269
1271
1272Debug::Context::Context(const int aSection, const int aLevel):
1273 section(aSection),
1274 level(aLevel),
1275 sectionLevel(Levels[aSection]),
1276 upper(Current),
1277 forceAlert(false),
1278 waitingForIdle(false)
1279{
1280 formatStream();
1281}
1282
1284void
1285Debug::Context::rewind(const int aSection, const int aLevel)
1286{
1287 section = aSection;
1288 level = aLevel;
1289 sectionLevel = Levels[aSection];
1290 assert(upper == Current);
1291 assert(!waitingForIdle);
1292
1293 buf.str(CompiledDebugMessageBody());
1294 buf.clear();
1295 // debugs() users are supposed to preserve format, but
1296 // some do not, so we have to waste cycles resetting it for all.
1297 formatStream();
1298}
1299
1301void
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
1312void
1314{
1315 if (!WaitingForIdle)
1316 return; // do not lock in vain because unlocking would calls us
1317
1318 const LoggingSectionGuard sectionGuard;
1319 while (const auto current = WaitingForIdle) {
1320 assert(current->waitingForIdle);
1321 LogMessage(*current);
1322 WaitingForIdle = current->upper;
1323 delete current;
1324 }
1325}
1326
1327std::ostringstream &
1328Debug::Start(const int section, const int level)
1329{
1330 Context *future = nullptr;
1331
1333 // a very rare reentrant debugs() call that originated during Finish() and such
1334 future = new Context(section, level);
1335 future->waitingForIdle = true;
1336 } else if (Current) {
1337 // a rare reentrant debugs() call that originated between Start() and Finish()
1338 future = new Context(section, level);
1339 } else {
1340 // Optimization: Nearly all debugs() calls get here; avoid allocations
1341 static Context *topContext = new Context(1, 1);
1342 topContext->rewind(section, level);
1343 future = topContext;
1344 }
1345
1346 Current = future;
1347
1348 return future->buf;
1349}
1350
1351void
1353{
1354 const LoggingSectionGuard sectionGuard;
1355
1356 // TODO: #include "base/CodeContext.h" instead if doing so works well.
1357 extern std::ostream &CurrentCodeContextDetail(std::ostream &os);
1358 if (Current->level <= DBG_IMPORTANT)
1360
1361 if (Current->waitingForIdle) {
1362 const auto past = Current;
1363 Current = past->upper;
1364 past->upper = nullptr;
1365 // do not delete `past` because we store it in WaitingForIdle below
1366
1367 // waitingForIdle messages are queued here instead of Start() because
1368 // their correct order is determined by the Finish() call timing/order.
1369 // Linear search, but this list ought to be very short (usually empty).
1370 auto *last = &WaitingForIdle;
1371 while (*last)
1372 last = &(*last)->upper;
1373 *last = past;
1374
1375 return;
1376 }
1377
1379 Current->forceAlert = false;
1380
1381 Context *past = Current;
1382 Current = past->upper;
1383 if (Current)
1384 delete past;
1385 // else it was a static topContext from Debug::Start()
1386}
1387
1388void
1390{
1391 // the ForceAlert(ostream) manipulator should only be used inside debugs()
1392 if (Current)
1393 Current->forceAlert = true;
1394}
1395
1396std::ostream&
1397ForceAlert(std::ostream& s)
1398{
1400 return s;
1401}
1402
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:238
void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final
write the corresponding debugs() message into the channel
Definition: debug.cc:636
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:744
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:753
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
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
struct timeval timestamp
approximate debugs() call time
Definition: debug.cc:112
~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:52
bool waitingForIdle
Definition: Stream.h:72
Context * upper
previous or parent record in nested debugging calls
Definition: Stream.h:66
std::ostringstream buf
debugs() output sink
Definition: Stream.h:67
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:68
void formatStream()
configures default formatting for the debugging stream
Definition: debug.cc:1302
void rewind(const int aSection, const int aLevel)
Optimization: avoids new Context creation for every debugs().
Definition: debug.cc:1285
Context(const int aSectionLevel, const int aLevel)
Definition: debug.cc:1272
static void ResetStderrLevel(int maxLevel)
Definition: debug.cc:699
static bool StderrEnabled()
Definition: debug.cc:725
static bool log_syslog
Definition: Stream.h:86
static void parseOptions(char const *)
Definition: debug.cc:1091
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:76
static Context * Current
deepest active context; nil outside debugs()
Definition: Stream.h:175
static void NameThisKid(int kidIdentifier)
Definition: debug.cc:405
static void LogMessage(const Context &)
broadcasts debugs() message to the logging channels
Definition: debug.cc:777
static int override_X
Definition: Stream.h:85
static void SettleSyslog()
Definition: debug.cc:1141
static int Levels[MAX_DEBUG_SECTIONS]
Definition: Stream.h:84
static void Finish()
logs output buffer created in Start() and closes debugging context
Definition: debug.cc:1352
static void NameThisHelper(const char *name)
Definition: debug.cc:382
static char * debugOptions
Definition: Stream.h:81
static void UseCacheLog()
Definition: debug.cc:1121
static char * cache_log
Definition: Stream.h:82
static std::ostringstream & Start(const int section, const int level)
opens debugging context and returns output buffer
Definition: debug.cc:1328
static std::ostream & Extra(std::ostream &os)
prefixes each grouped debugs() line after the first one in the group
Definition: Stream.h:114
static void BanCacheLogUse()
Definition: debug.cc:1114
static void ConfigureSyslog(const char *facility)
enables logging to syslog (using the specified facility, when not nil)
Definition: debug.cc:1079
static void StopCacheLogUse()
Definition: debug.cc:1128
static int Level()
minimum level required by the current debugs() call
Definition: Stream.h:101
static int rotateNumber
Definition: Stream.h:83
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:1313
static void ForceAlert()
configures the active debugging context to write syslog ALERT
Definition: debug.cc:1389
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
DebugChannel managing messages destined for "standard error stream" (stderr)
Definition: debug.cc:250
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
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
bool shouldWrite(const DebugMessageHeader &) const final
Definition: debug.cc:1069
bool opened
whether openlog() was called
Definition: debug.cc:287
void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final
write the corresponding debugs() message into the channel
Definition: debug.cc:1061
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:40
#define MAX_DEBUG_SECTIONS
Definition: Stream.h:34
#define DBG_IMPORTANT
Definition: Stream.h:38
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Stream.h:193
#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: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
static std::optional< int > ExplicitStderrLevel
Definition: debug.cc:43
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:1252
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:368
static Debug::Context * WaitingForIdle
Definition: debug.cc:345
static const char * debugLogTime(const timeval &)
Definition: debug.cc:1223
static void debugOpenLog(const char *logfile)
Definition: debug.cc:860
static int DefaultStderrLevel
Definition: debug.cc:51
void _db_rotate_log(void)
Definition: debug.cc:1156
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:1255
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 void debugArg(const char *arg)
Definition: debug.cc:822
#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 NULL
Definition: types.h:160
#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