src/debug/debug.cc

   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/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
  25 char *Debug::debugOptions = nullptr;
  26 int Debug::override_X = 0;
  27 bool Debug::log_syslog = false;
  28 int Debug::Levels[MAX_DEBUG_SECTIONS];
  29 char *Debug::cache_log = nullptr;
  30 int Debug::rotateNumber = -1;
  31
  32 /// a counter related to the number of debugs() calls
  33 using DebugRecordCount = uint64_t;
  34
  35 class DebugModule;
  36
  37 /// Debugging module singleton.
  38 static DebugModule *Module_ = nullptr;
  39
  40 /// Explicitly configured maximum level for debugs() messages written to stderr.
  41 /// debugs() messages with this (or lower) level will be written to stderr (and
  42 /// possibly other channels).
  43 static std::optional<int> ExplicitStderrLevel;
  44
  45 /// ExplicitStderrLevel preference or default: Just like with
  46 /// ExplicitStderrLevel, debugs() messages with this (or lower) level will be
  47 /// written to stderr (and possibly other channels), but this setting is ignored
  48 /// when ExplicitStderrLevel is set. This setting is also ignored after major
  49 /// problems that prevent logging of important debugs() messages (e.g., failing
  50 /// to open cache_log or assertions).
  51 static int DefaultStderrLevel = -1;
  52
  53 /// early debugs() with higher level are not buffered and, hence, may be lost
  54 static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
  55
  56 /// pre-formatted name of the current process for debugs() messages (or empty)
  57 static std::string ProcessLabel;
  58
  59 static const char *debugLogTime(const timeval &);
  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
  74 /// Whether ResetSections() has been called already. We need to keep track of
  75 /// this state because external code may trigger ResetSections() before the
  76 /// DebugModule constructor has a chance to ResetSections() to their defaults.
  77 /// TODO: Find a way to static-initialize Debug::Levels instead.
  78 static bool DidResetSections = false;
  79
  80 /// a named FILE with very-early/late usage safety mechanisms
  81 class DebugFile
  82 {
  83 public:
  84     DebugFile() {}
  85     ~DebugFile() { clear(); }
  86     DebugFile(DebugFile &&) = delete; // no copying or moving of any kind
  87
  88     /// switches to the new pair, absorbing FILE and duping the name
  89     void reset(FILE *newFile, const char *newName);
  90
  91     /// go back to the initial state
  92     void clear() { reset(nullptr, nullptr); }
  93
  94     /// an opened cache_log stream or nil
  95     FILE *file() { return file_; }
  96
  97     char *name = nullptr;
  98
  99 private:
 100     friend void ResyncDebugLog(FILE *newFile);
 101
 102     FILE *file_ = nullptr; ///< opened "real" file or nil; never stderr
 103 };
 104
 105 /// meta-information of a Finish()ed debugs() message
 106 class DebugMessageHeader
 107 {
 108 public:
 109     DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &);
 110
 111     DebugRecordCount recordNumber; ///< LogMessage() calls before this message
 112     struct timeval timestamp; ///< approximate debugs() call time
 113     int section; ///< debugs() section
 114     int level; ///< debugs() level
 115     bool forceAlert; ///< debugs() forceAlert flag
 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!
 123 /// The processed "content" (i.e. the last parameter) part of a debugs() call.
 124 using CompiledDebugMessageBody = std::string;
 125
 126 /// a fully processed debugs(), ready to be logged
 127 class CompiledDebugMessage
 128 {
 129 public:
 130     using Header = DebugMessageHeader;
 131     using Body = CompiledDebugMessageBody;
 132
 133     CompiledDebugMessage(const Header &, const Body &);
 134
 135     Header header; ///< debugs() meta-information; reflected in log line prefix
 136     Body body; ///< the log line after the prefix (without the newline)
 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.
 142 /// debugs() messages captured in LogMessage() call order
 143 using CompiledDebugMessages = std::deque<CompiledDebugMessage>;
 144
 145 /// a receiver of debugs() messages (e.g., stderr or cache.log)
 146 class DebugChannel
 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)
 155     DebugChannel(DebugChannel &&) = delete;
 156
 157     /// whether we are still expecting (and buffering) early messages
 158     bool collectingEarlyMessages() const { return bool(earlyMessages); }
 159
 160     /// end early message buffering, logging any saved messages
 161     void stopEarlyMessageCollection();
 162
 163     /// end early message buffering, without logging any saved messages
 164     /// \returns (a possibly empty container with) saved messages or nil
 165     EarlyMessages releaseEarlyMessages() { return EarlyMessages(earlyMessages.release()); }
 166
 167     /// Write the message to the channel if the channel accepts (such) messages.
 168     /// This writing may be delayed until the channel configuration is settled.
 169     void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 170
 171 protected:
 172     /// output iterator for writing CompiledDebugMessages to a given channel
 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
 184         Logger &operator=(const CompiledDebugMessage &message)
 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; ///< output destination
 200     };
 201
 202     /// whether we should write() the corresponding debugs() message now
 203     /// (assumes some higher-level code applied cache.log section/level filter)
 204     virtual bool shouldWrite(const DebugMessageHeader &) const = 0;
 205
 206     /// write the corresponding debugs() message into the channel
 207     virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) = 0;
 208
 209     /// stores the given early message (if possible) or forgets it (otherwise)
 210     void saveMessage(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 211
 212     /// stop saving and log() any "early" messages, in recordNumber order
 213     static void StopSavingAndLog(DebugChannel &, DebugChannel * = nullptr);
 214
 215     /// Formats a validated debugs() record and writes it to the given FILE.
 216     void writeToStream(FILE &, const DebugMessageHeader &, const CompiledDebugMessageBody &);
 217
 218     /// reacts to a written a debugs() message
 219     void noteWritten(const DebugMessageHeader &);
 220
 221 protected:
 222     const char * const name = nullptr; ///< unique channel label for debugging
 223
 224     /// the number of messages sent to the underlying channel so far
 225     DebugRecordCount written = 0;
 226
 227     /// DebugMessageHeader::recordNumber of the last message we wrote
 228     DebugRecordCount lastWrittenRecordNumber = 0;
 229
 230     /// debugs() messages waiting for the channel configuration to settle (and
 231     /// the channel to open) so that their eligibility for logging can be
 232     /// determined (and the messages can be actually written somewhere)
 233     EarlyMessages earlyMessages;
 234 };
 235
 236 /// DebugChannel managing messages destined for the configured cache_log file
 237 class CacheLogChannel: public DebugChannel
 238 {
 239 public:
 240     CacheLogChannel(): DebugChannel("cache_log") {}
 241
 242 protected:
 243     /* DebugChannel API */
 244     bool shouldWrite(const DebugMessageHeader &) const final;
 245     void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
 246 };
 247
 248 /// DebugChannel managing messages destined for "standard error stream" (stderr)
 249 class StderrChannel: public DebugChannel
 250 {
 251 public:
 252     StderrChannel(): DebugChannel("stderr") {}
 253
 254     /// start to take care of past/saved and future cacheLovirtual gChannel messages
 255     void takeOver(CacheLogChannel &);
 256
 257     /// stop providing a cache_log replacement (if we were providing it)
 258     void stopCoveringForCacheLog();
 259
 260     /// \copydoc DebugChannel::shouldWrite()
 261     bool enabled(const int messageDebugLevel) const;
 262
 263 protected:
 264     /* DebugChannel API */
 265     bool shouldWrite(const DebugMessageHeader &) const final;
 266     void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
 267
 268 private:
 269     /// whether we are the last resort for logging debugs() messages
 270     bool coveringForCacheLog = false;
 271 };
 272
 273 /// syslog DebugChannel
 274 class SyslogChannel: public DebugChannel
 275 {
 276 public:
 277     SyslogChannel(): DebugChannel("syslog") {}
 278
 279     void markOpened() { opened = true; }
 280
 281 protected:
 282     /* DebugChannel API */
 283     bool shouldWrite(const DebugMessageHeader &) const final;
 284     void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
 285
 286 private:
 287     bool opened = false; ///< whether openlog() was called
 288 };
 289
 290 /// Manages private module state that must be available during program startup
 291 /// and (especially) termination. Any non-trivial state objects must be
 292 /// encapsulated here because debugs() may be called before dynamic
 293 /// initialization or after the destruction of static objects in debug.cc.
 294 class DebugModule
 295 {
 296 public:
 297     DebugModule();
 298
 299     // we provide debugging services for the entire duration of the program
 300     ~DebugModule() = delete;
 301
 302     /// \copydoc Debug::PrepareToDie()
 303     void prepareToDie();
 304
 305     /// Log the given debugs() message to appropriate channel(s) (eventually).
 306     /// Assumes the message has passed the global section/level filter.
 307     void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 308
 309     /// Start using an open cache_log file as the primary debugs() destination.
 310     /// Stop using stderr as a cache_log replacement (if we were doing that).
 311     void useCacheLog();
 312
 313     /// Start using stderr as the primary debugs() destination.
 314     /// Stop waiting for an open cache_log file (if we were doing that).
 315     void banCacheLogUse();
 316
 317 public:
 318     CacheLogChannel cacheLogChannel;
 319     StderrChannel stderrChannel;
 320     SyslogChannel syslogChannel;
 321 };
 322
 323 /// Maintains the number of code paths on the current call stack that need
 324 /// protection from new debugs() calls. Squid cannot _block_ re-entrant debugs()
 325 /// calls, but the high-level debugs() handling code queues re-entrant logging
 326 /// attempts when Busy() instead of letting them through to sensitive code.
 327 class LoggingSectionGuard
 328 {
 329 public:
 330     LoggingSectionGuard();
 331     ~LoggingSectionGuard();
 332
 333     /// whether new debugs() messages must be queued
 334     static bool Busy() { return LoggingConcurrencyLevel; }
 335
 336 private:
 337     /// the current number of protected callers
 338     static size_t LoggingConcurrencyLevel;
 339 };
 340
 341 size_t LoggingSectionGuard::LoggingConcurrencyLevel = 0;
 342
 343 /// debugs() messages postponed due to LoggingSectionGuard::Busy(). This is the
 344 /// head of the invasive Context::upper FIFO list of such messages.
 345 static Debug::Context *WaitingForIdle = nullptr;
 346
 347 /// cache_log file
 348 /// safe during static initialization, even if it has not been constructed yet
 349 /// safe during program termination, even if it has been destructed already
 350 static DebugFile TheLog;
 351
 352 FILE *
 353 DebugStream() {
 354     return TheLog.file() ? TheLog.file() : stderr;
 355 }
 356
 357 /// used for the side effect: fills Debug::Levels with the given level
 358 static void
 359 ResetSections(const int level)
 360 {
 361     DidResetSections = true;
 362     for (auto &sectionLevel: Debug::Levels)
 363         sectionLevel = level;
 364 }
 365
 366 /// optimization: formats ProcessLabel once for frequent debugs() reuse
 367 static void
 368 LabelThisProcess(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
 381 void
 382 Debug::NameThisHelper(const char * const name)
 383 {
 384     LabelThisProcess(name);
 385
 386     if (const auto parentProcessDebugOptions = getenv("SQUID_DEBUG")) {
 387         assert(!debugOptions);
 388         debugOptions = xstrdup(parentProcessDebugOptions);
 389     }
 390
 391     // do not restrict helper (i.e. stderr) logging beyond debug_options
 392     EnsureDefaultStderrLevel(DBG_DATA);
 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", std::optional<int>(kidIdentifier));
 411     else
 412         ProcessLabel.clear(); // probably already empty
 413 }
 414
 415 /* LoggingSectionGuard */
 416
 417 LoggingSectionGuard::LoggingSectionGuard()
 418 {
 419     ++LoggingConcurrencyLevel;
 420 }
 421
 422 LoggingSectionGuard::~LoggingSectionGuard()
 423 {
 424     if (--LoggingConcurrencyLevel == 0)
 425         Debug::LogWaitingForIdle();
 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.
 433 DebugModule::DebugModule()
 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
 445 DebugModule::log(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
 446 {
 447     cacheLogChannel.log(header, body);
 448     stderrChannel.log(header, body);
 449     syslogChannel.log(header, body);
 450 }
 451
 452 void
 453 DebugModule::prepareToDie()
 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.
 459     if (cacheLogChannel.collectingEarlyMessages() && !TheLog.file())
 460         banCacheLogUse();
 461
 462     cacheLogChannel.stopEarlyMessageCollection();
 463     stderrChannel.stopEarlyMessageCollection();
 464     syslogChannel.stopEarlyMessageCollection();
 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.
 474     Debug::LogWaitingForIdle();
 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
 482 DebugModule::useCacheLog()
 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
 490 DebugModule::banCacheLogUse()
 491 {
 492     assert(!TheLog.file());
 493     stderrChannel.takeOver(cacheLogChannel);
 494 }
 495
 496 /// safe access to the debugging module
 497 static
 498 DebugModule &
 499 Module()
 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.
 505         Debug::SettleSyslog();
 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
 527 DebugChannel::stopEarlyMessageCollection()
 528 {
 529     if (earlyMessages)
 530         StopSavingAndLog(*this);
 531     // else already stopped
 532 }
 533
 534 void
 535 DebugChannel::log(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
 536 {
 537     if (header.recordNumber <= lastWrittenRecordNumber)
 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.
 546     stopEarlyMessageCollection();
 547
 548     write(header, body);
 549 }
 550
 551 void
 552 Debug::ForgetSaved()
 553 {
 554     auto &module = Module();
 555     (void)module.cacheLogChannel.releaseEarlyMessages();
 556     (void)module.stderrChannel.releaseEarlyMessages();
 557     (void)module.syslogChannel.releaseEarlyMessages();
 558 }
 559
 560 void
 561 Debug::PrepareToDie()
 562 {
 563     Module().prepareToDie();
 564 }
 565
 566 void
 567 DebugChannel::StopSavingAndLog(DebugChannel &channelA, DebugChannel *channelBOrNil)
 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
 592 DebugChannel::saveMessage(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
 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
 621 DebugChannel::noteWritten(const DebugMessageHeader &header)
 622 {
 623     ++written;
 624     lastWrittenRecordNumber = header.recordNumber;
 625 }
 626
 627 /* CacheLogChannel */
 628
 629 bool
 630 CacheLogChannel::shouldWrite(const DebugMessageHeader &) const
 631 {
 632     return TheLog.file();
 633 }
 634
 635 void
 636 CacheLogChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
 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
 659 StderrChannel::shouldWrite(const DebugMessageHeader &header) const
 660 {
 661     return enabled(header.level);
 662 }
 663
 664 void
 665 StderrChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
 666 {
 667     writeToStream(*stderr, header, body);
 668 }
 669
 670 void
 671 StderrChannel::takeOver(CacheLogChannel &cacheLogChannel)
 672 {
 673     if (coveringForCacheLog)
 674         return;
 675     coveringForCacheLog = true;
 676
 677     StopSavingAndLog(*this, &cacheLogChannel);
 678 }
 679
 680 void
 681 StderrChannel::stopCoveringForCacheLog()
 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
 705 Debug::SettleStderr()
 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";
 717         if (ExplicitStderrLevel)
 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
 725 Debug::StderrEnabled()
 726 {
 727     return Module().stderrChannel.enabled(DBG_CRITICAL);
 728 }
 729
 730 /* DebugMessageHeader */
 731
 732 DebugMessageHeader::DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &context):
 733     recordNumber(aRecordNumber),
 734     section(context.section),
 735     level(context.level),
 736     forceAlert(context.forceAlert)
 737 {
 738     (void)getCurrentTime(); // update current_time
 739     timestamp = current_time;
 740 }
 741
 742 /* CompiledDebugMessage */
 743
 744 CompiledDebugMessage::CompiledDebugMessage(const Header &aHeader, const Body &aBody):
 745     header(aHeader),
 746     body(aBody)
 747 {
 748 }
 749
 750 /* DebugFile */
 751
 752 void
 753 DebugFile::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_)
 765         fd_open(fileno(file_), FD_LOG, Debug::cache_log);
 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
 775 /// broadcasts debugs() message to the logging channels
 776 void
 777 Debug::LogMessage(const Context &context)
 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
 821 static void
 822 debugArg(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
 859 static void
 860 debugOpenLog(const char *logfile)
 861 {
 862     assert(logfile);
 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);
 876         Module().useCacheLog();
 877     } else {
 878         const auto xerrno = errno;
 879         TheLog.clear();
 880         Module().banCacheLogUse();
 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
 892 static struct syslog_facility_name {
 893     const char *name;
 894     int facility;
 895 }
 896
 897 syslog_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
1006 static 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
1044 static int
1045 SyslogPriority(const DebugMessageHeader &header)
1046 {
1047     return header.forceAlert ? LOG_ALERT :
1048            (header.level == 0 ? LOG_WARNING : LOG_NOTICE);
1049 }
1050
1051 void
1052 SyslogChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body)
1053 {
1054     syslog(SyslogPriority(header), "%s", body.c_str());
1055     noteWritten(header);
1056 }
1057
1058 #else
1059
1060 void
1061 SyslogChannel::write(const DebugMessageHeader &, const CompiledDebugMessageBody &)
1062 {
1063     assert(!"unreachable code because opened, shouldWrite() are always false");
1064 }
1065
1066 #endif /* HAVE_SYSLOG */
1067
1068 bool
1069 SyslogChannel::shouldWrite(const DebugMessageHeader &header) const
1070 {
1071     if (!opened)
1072         return false;
1073
1074     assert(Debug::log_syslog);
1075     return header.forceAlert || header.level <= DBG_IMPORTANT;
1076 }
1077
1078 void
1079 Debug::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
1090 void
1091 Debug::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
1113 void
1114 Debug::BanCacheLogUse()
1115 {
1116     Debug::parseOptions(debugOptions);
1117     Module().banCacheLogUse();
1118 }
1119
1120 void
1121 Debug::UseCacheLog()
1122 {
1123     Debug::parseOptions(debugOptions);
1124     debugOpenLog(cache_log);
1125 }
1126
1127 void
1128 Debug::StopCacheLogUse()
1129 {
1130     if (TheLog.file()) {
1131         // UseCacheLog() was successful.
1132         Module().cacheLogChannel.stopEarlyMessageCollection(); // paranoid
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
1140 void
1141 Debug::SettleSyslog()
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);
1147         Module().syslogChannel.markOpened();
1148     }
1149
1150 #endif /* HAVE_SYSLOG */
1151
1152     Module().syslogChannel.stopEarlyMessageCollection();
1153 }
1154
1155 void
1156 _db_rotate_log(void)
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.
1219     debugOpenLog(Debug::cache_log);
1220 }
1221
1222 static const char *
1223 debugLogTime(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
1250 /// Whether there are any xassert() calls in the call stack. Treat as private to
1251 /// xassert(): It is moved out only to simplify the asserting code path.
1252 static auto Asserting_ = false;
1253
1254 void
1255 xassert(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
1266     Debug::PrepareToDie();
1267     abort();
1268 }
1269
1270 Debug::Context *Debug::Current = nullptr;
1271
1272 Debug::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
1283 /// Optimization: avoids new Context creation for every debugs().
1284 void
1285 Debug::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
1300 /// configures default formatting for the debugging stream
1301 void
1302 Debug::Context::formatStream()
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
1312 void
1313 Debug::LogWaitingForIdle()
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
1327 std::ostringstream &
1328 Debug::Start(const int section, const int level)
1329 {
1330     Context *future = nullptr;
1331
1332     if (LoggingSectionGuard::Busy()) {
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
1351 void
1352 Debug::Finish()
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)
1359         Current->buf << CurrentCodeContextDetail;
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
1378     LogMessage(*Current);
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
1388 void
1389 Debug::ForceAlert()
1390 {
1391     //  the ForceAlert(ostream) manipulator should only be used inside debugs()
1392     if (Current)
1393         Current->forceAlert = true;
1394 }
1395
1396 std::ostream&
1397 ForceAlert(std::ostream& s)
1398 {
1399     Debug::ForceAlert();
1400     return s;
1401 }
1402