From d7ca82e66dadd85b96b7b2f21866c92e745921ef Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Sat, 29 Feb 2020 05:59:35 +0000 Subject: [PATCH] Bug 4796: comm.cc !isOpen(conn->fd) assertion when rotating logs (#474) This long-term solution overrides the short-term fix at 2cd72a2. Now, debug.cc correctly maintains meta information associated with its file descriptors. IMO, the correct place for calling _db_init() is just after locking the PID file because we want to log ASAP, but cache.log is a common resource that requires protection. Thus, the two old _db_init() calls were both excessive and misplaced: * The first call happens too early, allowing another Squid instance to pollute cache.log with messages unrelated to the cache.log-owning instance (e.g., a "FATAL: Squid is already running" message when attempting to start another instance). * The second call happens too late, missing earlier debugs() that ought to be written into cache.log (e.g., debugs() in comm_init()). Fixing _db_init() calls led to adjustments like moving mainSetCwd() to be called prior to the relocated _db_init(). However, these changes should not affect chroot-sensitive code such as UseConfigRunners(). Some early debugs() messages are no longer written into cache.log: * Exception messages like "Squid is already running" emitted by another Squid instance. This is an improvement: Messages about other instances do not belong to the cache.log locked by the running instance. * Messages (mostly errors and warning) from "finalizeConfig" callers (e.g., "WARNING: mem-cache size is too small..."). This loss is regrettable. Long-term, these messages should be reported after configuration is finalized (TODO). Delayed reporting will also help when Squid starts rejecting invalid reconfigurations. * Messages from a few early enter_suid()/leave_suid() calls, such as "enter_suid: PID" and "leave_suid: PID". This is an improvement: These debugging messages pollute cache.log. * A few early SquidMain() messages emitted between parseConfigFile() and StartUsingConfig() (e.g., "Doing post-config initialization"). This is an improvement: These debugging messages pollute cache.log. Also removed outdated 'TEST_ACCESS' hack for simplicity sake. Also marked an old XXX: Chrooted SMP master process does not db_init(). --- src/cache_cf.cc | 7 ---- src/comm.cc | 3 +- src/debug.cc | 8 ++++- src/fde.cc | 7 ++++ src/fde.h | 7 ++++ src/icmp/Makefile.am | 4 +++ src/main.cc | 80 +++++++++++++++++++++++++------------------ src/tests/testRock.cc | 3 ++ src/tests/testUfs.cc | 3 ++ 9 files changed, 78 insertions(+), 44 deletions(-) diff --git a/src/cache_cf.cc b/src/cache_cf.cc index 26c8ca6b52..ff90b9f55b 100644 --- a/src/cache_cf.cc +++ b/src/cache_cf.cc @@ -607,13 +607,6 @@ parseConfigFileOrThrow(const char *file_name) */ configDoConfigure(); - if (!Config.chroot_dir) { - leave_suid(); - setUmask(Config.umask); - _db_init(Debug::cache_log, Debug::debugOptions); - enter_suid(); - } - if (opt_send_signal == -1) { Mgr::RegisterAction("config", "Current Squid Configuration", diff --git a/src/comm.cc b/src/comm.cc index abbcbacf4a..804cf10ad2 100644 --- a/src/comm.cc +++ b/src/comm.cc @@ -1232,7 +1232,7 @@ commSetTcpKeepalive(int fd, int idle, int interval, int timeout) void comm_init(void) { - fd_table =(fde *) xcalloc(Squid_MaxFD, sizeof(fde)); + assert(fd_table); /* make sure the accept() socket FIFO delay queue exists */ Comm::AcceptLimiter::Instance(); @@ -1258,7 +1258,6 @@ comm_exit(void) delete TheHalfClosed; TheHalfClosed = NULL; - safe_free(fd_table); Comm::CallbackTableDestruct(); } diff --git a/src/debug.cc b/src/debug.cc index 2bbdc37ba5..8ef89602fb 100644 --- a/src/debug.cc +++ b/src/debug.cc @@ -10,6 +10,7 @@ #include "squid.h" #include "Debug.h" +#include "fd.h" #include "ipc/Kids.h" #include "SquidTime.h" #include "util.h" @@ -96,10 +97,15 @@ DebugFile::reset(FILE *newFile, const char *newName) // callers must use nullptr instead of the used-as-the-last-resort stderr assert(newFile != stderr || !stderr); - if (file_) + if (file_) { + fd_close(fileno(file_)); fclose(file_); + } file_ = newFile; // may be nil + if (file_) + fd_open(fileno(file_), FD_LOG, Debug::cache_log); + xfree(name); name = newName ? xstrdup(newName) : nullptr; diff --git a/src/fde.cc b/src/fde.cc index e4d492bb43..7f992d38ae 100644 --- a/src/fde.cc +++ b/src/fde.cc @@ -138,3 +138,10 @@ fde::remoteAddr() const return buf; } +void +fde::Init() +{ + assert(!Table); + Table = static_cast(xcalloc(Squid_MaxFD, sizeof(fde))); +} + diff --git a/src/fde.h b/src/fde.h index c917e3577b..bc9e0665bf 100644 --- a/src/fde.h +++ b/src/fde.h @@ -52,6 +52,13 @@ class fde { public: + + // TODO: Merge with comm_init() to reduce initialization order dependencies. + /// Configures fd_table (a.k.a. fde::Table). + /// Call once, after learning the number of supported descriptors (i.e. + /// setMaxFD()) and before dereferencing fd_table (e.g., before Comm I/O). + static void Init(); + fde() { *ipaddr = 0; *desc = 0; diff --git a/src/icmp/Makefile.am b/src/icmp/Makefile.am index 89870e6f15..a5edcb54cd 100644 --- a/src/icmp/Makefile.am +++ b/src/icmp/Makefile.am @@ -40,6 +40,7 @@ COPIED_SOURCE= \ globals.cc \ SquidConfig.cc \ SquidNew.cc \ + stub_fd.cc \ stub_HelperChildConfig.cc \ stub_libmem.cc \ stub_SBuf.cc \ @@ -101,6 +102,9 @@ SquidNew.cc: $(top_srcdir)/src/SquidNew.cc stub_HelperChildConfig.cc: $(top_srcdir)/src/tests/stub_HelperChildConfig.cc cp $(top_srcdir)/src/tests/stub_HelperChildConfig.cc $@ +stub_fd.cc: $(top_srcdir)/src/tests/stub_fd.cc STUB.h + cp $(top_srcdir)/src/tests/stub_fd.cc $@ + stub_libmem.cc: $(top_srcdir)/src/tests/stub_libmem.cc STUB.h cp $(top_srcdir)/src/tests/stub_libmem.cc $@ diff --git a/src/main.cc b/src/main.cc index 1807311124..949386d02a 100644 --- a/src/main.cc +++ b/src/main.cc @@ -1132,9 +1132,6 @@ mainSetCwd(void) static void mainInitialize(void) { - /* chroot if configured to run inside chroot */ - mainSetCwd(); - if (opt_catch_signals) { squid_signal(SIGSEGV, death, SA_NODEFER | SA_RESETHAND); squid_signal(SIGBUS, death, SA_NODEFER | SA_RESETHAND); @@ -1149,12 +1146,6 @@ mainInitialize(void) if (icpPortNumOverride != 1) Config.Port.icp = (unsigned short) icpPortNumOverride; - _db_init(Debug::cache_log, Debug::debugOptions); - - // Do not register cache.log descriptor with Comm (for now). - // See https://bugs.squid-cache.org/show_bug.cgi?id=4796 - // fd_open(fileno(debug_log), FD_LOG, Debug::cache_log); - debugs(1, DBG_CRITICAL, "Starting Squid Cache version " << version_string << " for " << CONFIG_HOST_TYPE << "..."); debugs(1, DBG_CRITICAL, "Service Name: " << service_name); @@ -1443,12 +1434,57 @@ ConfigureCurrentKid(const CommandLine &cmdLine) } } -static void StartUsingConfig() +/// Start directing debugs() messages to the configured cache.log. +/// Until this function is called, all allowed messages go to stderr. +static void +ConfigureDebugging() +{ + if (opt_no_daemon) { + fd_open(0, FD_LOG, "stdin"); + fd_open(1, FD_LOG, "stdout"); + fd_open(2, FD_LOG, "stderr"); + } + // we should not create cache.log outside chroot environment, if any + // XXX: With Config.chroot_dir set, SMP master process never calls db_init(). + if (!Config.chroot_dir || Chrooted) + _db_init(Debug::cache_log, Debug::debugOptions); +} + +static void +RunConfigUsers() { RunRegisteredHere(RegisteredRunner::claimMemoryNeeds); RunRegisteredHere(RegisteredRunner::useConfig); } +static void +StartUsingConfig() +{ + setMaxFD(); + fde::Init(); + const auto skipCwdAdjusting = IamMasterProcess() && InDaemonMode(); + if (skipCwdAdjusting) { + ConfigureDebugging(); + RunConfigUsers(); + } else if (Config.chroot_dir) { + RunConfigUsers(); + enter_suid(); + // TODO: don't we need to RunConfigUsers() in the configured + // chroot environment? + mainSetCwd(); + leave_suid(); + ConfigureDebugging(); + } else { + ConfigureDebugging(); + RunConfigUsers(); + enter_suid(); + // TODO: since RunConfigUsers() may use a relative path, we + // need to change the process root first + mainSetCwd(); + leave_suid(); + } +} + int SquidMain(int argc, char **argv) { @@ -1585,18 +1621,6 @@ SquidMain(int argc, char **argv) if (opt_send_signal == -1 && IamMasterProcess()) Instance::ThrowIfAlreadyRunning(); -#if TEST_ACCESS - - comm_init(); - - mainInitialize(); - - test_access(); - - return 0; - -#endif - /* send signal to running copy and exit */ if (opt_send_signal != -1) { /* chroot if configured to run inside chroot */ @@ -1628,9 +1652,6 @@ SquidMain(int argc, char **argv) enter_suid(); if (opt_create_swap_dirs) { - /* chroot if configured to run inside chroot */ - mainSetCwd(); - setEffectiveUser(); debugs(0, DBG_CRITICAL, "Creating missing swap directories"); Store::Root().create(); @@ -1642,18 +1663,9 @@ SquidMain(int argc, char **argv) CpuAffinityCheck(); CpuAffinityInit(); - setMaxFD(); - /* init comm module */ comm_init(); - if (opt_no_daemon) { - /* we have to init fdstat here. */ - fd_open(0, FD_LOG, "stdin"); - fd_open(1, FD_LOG, "stdout"); - fd_open(2, FD_LOG, "stderr"); - } - #if USE_WIN32_SERVICE WIN32_svcstatusupdate(SERVICE_START_PENDING, 10000); diff --git a/src/tests/testRock.cc b/src/tests/testRock.cc index 7f93ac0dff..d9634d3186 100644 --- a/src/tests/testRock.cc +++ b/src/tests/testRock.cc @@ -9,6 +9,7 @@ #include "squid.h" #include "ConfigParser.h" #include "DiskIO/DiskIOModule.h" +#include "fde.h" #include "fs/rock/RockSwapDir.h" #include "globals.h" #include "HttpHeader.h" @@ -142,6 +143,8 @@ testRock::commonInit() Mem::Init(); + fde::Init(); + comm_init(); httpHeaderInitModule(); /* must go before any header processing (e.g. the one in errorInitialize) */ diff --git a/src/tests/testUfs.cc b/src/tests/testUfs.cc index e5728af5a7..0071151870 100644 --- a/src/tests/testUfs.cc +++ b/src/tests/testUfs.cc @@ -8,6 +8,7 @@ #include "squid.h" #include "DiskIO/DiskIOModule.h" +#include "fde.h" #include "fs/ufs/UFSSwapDir.h" #include "globals.h" #include "HttpHeader.h" @@ -72,6 +73,8 @@ testUfs::commonInit() Mem::Init(); + fde::Init(); + comm_init(); httpHeaderInitModule(); /* must go before any header processing (e.g. the one in errorInitialize) */ -- 2.39.5