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 
26 int Debug::override_X = 0;
27 bool Debug::log_syslog = false;
29 char *Debug::cache_log = NULL;
30 int Debug::rotateNumber = -1;
31 
33 using DebugRecordCount = uint64_t;
34 
35 class DebugModule;
36 
38 static DebugModule *Module_ = nullptr;
39 
44 
51 static int DefaultStderrLevel = -1;
52 
54 static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
55 
57 static std::string ProcessLabel;
58 
59 static const char *debugLogTime(time_t t);
60 
61 #if HAVE_SYSLOG
62 #ifdef LOG_LOCAL4
63 static int syslog_facility = 0;
64 #endif
65 #endif
66 
67 #if _SQUID_WINDOWS_
68 extern LPCRITICAL_SECTION dbg_mutex;
69 typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
70 #endif
71 
72 static void ResetSections(const int level = DBG_IMPORTANT);
73 
78 static bool DidResetSections = false;
79 
81 class DebugFile
82 {
83 public:
84  DebugFile() {}
85  ~DebugFile() { clear(); }
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 
99 private:
100  friend void ResyncDebugLog(FILE *newFile);
101 
102  FILE *file_ = nullptr;
103 };
104 
107 {
108 public:
109  DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &);
110 
112  time_t timestamp;
113  int section;
114  int level;
115  bool forceAlert;
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!
124 using CompiledDebugMessageBody = std::string;
125 
128 {
129 public:
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.
143 using CompiledDebugMessages = std::deque<CompiledDebugMessage>;
144 
147 {
148 public:
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 
171 protected:
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 
221 protected:
222  const char * const name = nullptr;
223 
226 
229 
234 };
235 
238 {
239 public:
240  CacheLogChannel(): DebugChannel("cache_log") {}
241 
242 protected:
243  /* DebugChannel API */
244  virtual bool shouldWrite(const DebugMessageHeader &) const final;
245  virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
246 };
247 
250 {
251 public:
252  StderrChannel(): DebugChannel("stderr") {}
253 
255  void takeOver(CacheLogChannel &);
256 
259 
261  bool enabled(const int messageDebugLevel) const;
262 
263 protected:
264  /* DebugChannel API */
265  virtual bool shouldWrite(const DebugMessageHeader &) const final;
266  virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
267 
268 private:
270  bool coveringForCacheLog = false;
271 };
272 
275 {
276 public:
277  SyslogChannel(): DebugChannel("syslog") {}
278 
279  void markOpened() { opened = true; }
280 
281 protected:
282  /* DebugChannel API */
283  virtual bool shouldWrite(const DebugMessageHeader &) const final;
284  virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
285 
286 private:
287  bool opened = false;
288 };
289 
295 {
296 public:
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 
317 public:
321 };
322 
328 {
329 public:
332 
334  static bool Busy() { return LoggingConcurrencyLevel; }
335 
336 private:
338  static size_t LoggingConcurrencyLevel;
339 };
340 
342 
345 static Debug::Context *WaitingForIdle = nullptr;
346 
351 
352 FILE *
354  return TheLog.file() ? TheLog.file() : stderr;
355 }
356 
358 static void
359 ResetSections(const int level)
360 {
361  DidResetSections = true;
362  for (auto &sectionLevel: Debug::Levels)
363  sectionLevel = level;
364 }
365 
367 static void
368 LabelThisProcess(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 
381 void
382 Debug::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
396  BanCacheLogUse();
397 
398  SettleStderr();
399  SettleSyslog();
400 
401  debugs(84, 2, "starting " << name << " with PID " << getpid());
402 }
403 
404 void
405 Debug::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)
441  ResetSections();
442 }
443 
444 void
446 {
447  cacheLogChannel.log(header, body);
448  stderrChannel.log(header, body);
449  syslogChannel.log(header, body);
450 }
451 
452 void
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.
460  banCacheLogUse();
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 
481 void
483 {
484  assert(TheLog.file());
485  stderrChannel.stopCoveringForCacheLog(); // in case it was covering
486  cacheLogChannel.stopEarlyMessageCollection(); // in case it was collecting
487 }
488 
489 void
491 {
492  assert(!TheLog.file());
494 }
495 
497 static
498 DebugModule &
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 
512 void
513 ResyncDebugLog(FILE *newFile)
514 {
515  TheLog.file_ = newFile;
516 }
517 
518 /* DebugChannel */
519 
520 DebugChannel::DebugChannel(const char * const aName):
521  name(aName),
522  earlyMessages(new CompiledDebugMessages())
523 {
524 }
525 
526 void
528 {
529  if (earlyMessages)
530  StopSavingAndLog(*this);
531  // else already stopped
532 }
533 
534 void
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 
551 void
553 {
554  auto &module = Module();
555  (void)module.cacheLogChannel.releaseEarlyMessages();
556  (void)module.stderrChannel.releaseEarlyMessages();
557  (void)module.syslogChannel.releaseEarlyMessages();
558 }
559 
560 void
562 {
563  Module().prepareToDie();
564 }
565 
566 void
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 
591 void
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 
610 void
611 DebugChannel::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 
620 void
622 {
623  ++written;
625 }
626 
627 /* CacheLogChannel */
628 
629 bool
631 {
632  return TheLog.file();
633 }
634 
635 void
637 {
638  writeToStream(*TheLog.file(), header, body);
639  fflush(TheLog.file());
640 }
641 
642 /* StderrChannel */
643 
644 bool
645 StderrChannel::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 
658 bool
660 {
661  return enabled(header.level);
662 }
663 
664 void
666 {
667  writeToStream(*stderr, header, body);
668 }
669 
670 void
672 {
674  return;
675  coveringForCacheLog = true;
676 
677  StopSavingAndLog(*this, &cacheLogChannel);
678 }
679 
680 void
682 {
683  if (!coveringForCacheLog)
684  return;
685 
686  coveringForCacheLog = false;
687  debugs(0, DBG_IMPORTANT, "Resuming logging to cache_log");
688 }
689 
690 void
691 Debug::EnsureDefaultStderrLevel(const int maxDefault)
692 {
693  if (DefaultStderrLevel < maxDefault)
694  DefaultStderrLevel = maxDefault; // may set or increase
695  // else: somebody has already requested a more permissive maximum
696 }
697 
698 void
699 Debug::ResetStderrLevel(const int maxLevel)
700 {
701  ExplicitStderrLevel = maxLevel; // may set, increase, or decrease
702 }
703 
704 void
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 
724 bool
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 
751 void
752 DebugFile::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 
775 void
776 Debug::LogMessage(const Context &context)
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 
820 static void
821 debugArg(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 
858 static void
859 debugOpenLog(const char *logfile)
860 {
861  assert(logfile);
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);
875  Module().useCacheLog();
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 
891 static struct syslog_facility_name {
892  const char *name;
893  int facility;
894 }
895 
896 syslog_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  NULL, 0
1000  }
1001 };
1002 
1003 #endif
1004 
1005 static 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 
1043 static int
1044 SyslogPriority(const DebugMessageHeader &header)
1045 {
1046  return header.forceAlert ? LOG_ALERT :
1047  (header.level == 0 ? LOG_WARNING : LOG_NOTICE);
1048 }
1049 
1050 void
1052 {
1053  syslog(SyslogPriority(header), "%s", body.c_str());
1054  noteWritten(header);
1055 }
1056 
1057 #else
1058 
1059 void
1061 {
1062  assert(!"unreachable code because opened, shouldWrite() are always false");
1063 }
1064 
1065 #endif /* HAVE_SYSLOG */
1066 
1067 bool
1069 {
1070  if (!opened)
1071  return false;
1072 
1074  return header.forceAlert || header.level <= DBG_IMPORTANT;
1075 }
1076 
1077 void
1078 Debug::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 
1089 void
1090 Debug::parseOptions(char const *options)
1091 {
1092  char *p = NULL;
1093  char *s = NULL;
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(NULL, w_space))
1106  debugArg(s);
1107 
1108  xfree(p);
1109  }
1110 }
1111 
1112 void
1114 {
1116  Module().banCacheLogUse();
1117 }
1118 
1119 void
1121 {
1124 }
1125 
1126 void
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 
1139 void
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 
1154 void
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 
1221 static const char *
1222 debugLogTime(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 
1251 static auto Asserting_ = false;
1252 
1253 void
1254 xassert(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 
1269 Debug::Context *Debug::Current = nullptr;
1270 
1271 Debug::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 
1283 void
1284 Debug::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 
1300 void
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 
1311 void
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 
1326 std::ostringstream &
1327 Debug::Start(const int section, const int level)
1328 {
1329  Context *future = nullptr;
1330 
1331  if (LoggingSectionGuard::Busy()) {
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 
1350 void
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 
1377  LogMessage(*Current);
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 
1387 void
1389 {
1390  // the ForceAlert(ostream) manipulator should only be used inside debugs()
1391  if (Current)
1392  Current->forceAlert = true;
1393 }
1394 
1395 std::ostream&
1396 ForceAlert(std::ostream& s)
1397 {
1399  return s;
1400 }
1401 
std::ostream & CurrentCodeContextDetail(std::ostream &os)
Definition: CodeContext.cc:94
#define false
Definition: GnuRegex.c:233
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
Logger & operator++(int)
Definition: debug.cc:195
std::reference_wrapper< DebugChannel > channel
output destination
Definition: debug.cc:199
Logger & operator++()
Definition: debug.cc:194
std::output_iterator_tag iterator_category
Definition: debug.cc:180
Logger & operator=(const CompiledDebugMessage &message)
Definition: debug.cc:184
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
FILE * file()
an opened cache_log stream or nil
Definition: debug.cc:95
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
~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 std::ostream & Extra(std::ostream &os)
prefixes each grouped debugs() line after the first one in the group
Definition: Stream.h:117
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 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:29
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:140
@ 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
void ResyncDebugLog(FILE *newFile)
a hack for low-level file descriptor manipulations in ipcCreate()
Definition: debug.cc:513
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 DebugModule & Module()
safe access to the debugging module
Definition: debug.cc:499
static void debugOpenLog(const char *logfile)
Definition: debug.cc:859
FILE * DebugStream()
Definition: debug.cc:353
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