src/debug/debug.cc

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