Bug 3819: "fd >= 0" assertion in file_write() during reconfiguration

Other possible assertions include "NumberOfUFSDirs" in UFSSwapDir and
"fd >= 0" in file_close(). And Fs::Ufs::UFSStoreState::drainWriteQueue()
may segfault while dereferencing nil theFile, although I am not sure
that bug is caused specifically by reconfiguration.

Since trunk r9181.3.1, reconfiguration is done in at least two steps:
First, mainReconfigureStart() closes/cleans/disables all modules
supporting hot reconfiguration and then, at the end of the event loop
iteration, mainReconfigureFinish() opens/configures/enables them again.
UFS code hits assertions if it has to log entries or rebuild swap.state
between those two steps. The tiny assertion opportunity window hides
these bugs from most proxies that are not doing enough disk I/O or are
not being reconfigured frequently enough.

Asynchronous UFS cache_dirs such as diskd were the most exposed, but
even blocking UFS caching code could probably hit [rebuild] assertions.

The swap.state rebuilding (always initiated at startup) probably did not
work as intended if reconfiguration happened during the rebuild time
because reconfiguration closed the swap.state file being rebuilt. We now
protect that swap.state file and delay rebuilding progress until
reconfiguration is over.

TODO: To squash more similar bugs, we need to move hot reconfiguration
support into the modules so that each module can reconfigure instantly.

diff --git a/src/fs/ufs/RebuildState.cc b/src/fs/ufs/RebuildState.cc
index 443faa66763bf5bcca7f85f14ad7e8c7230cff6e..c0dff12201d1ed26ef92dfda3f618520582d0034 100644 (file)
--- a/src/fs/ufs/RebuildState.cc
+++ b/src/fs/ufs/RebuildState.cc
@@ -74,9 +74,11 @@ void
 Fs::Ufs::RebuildState::RebuildStep(void *data)
 {
     RebuildState *rb = (RebuildState *)data;
-    rb->rebuildStep();
+    if (!reconfiguring)
+        rb->rebuildStep();
 
-    if (!rb->isDone())
+    // delay storeRebuildComplete() when reconfiguring to protect storeCleanup()
+    if (!rb->isDone() || reconfiguring)
         eventAdd("storeRebuild", RebuildStep, rb, 0.01, 1);
     else {
         -- StoreController::store_dirs_rebuilding;

diff --git a/src/fs/ufs/UFSStoreState.cc b/src/fs/ufs/UFSStoreState.cc
index a418e845f8f0cc846271ba4cef2fb982f4b20dfb..9e621fbfa54e66477a5fe8c236fcf498f1da8b2c 100644 (file)
--- a/src/fs/ufs/UFSStoreState.cc
+++ b/src/fs/ufs/UFSStoreState.cc
@@ -421,7 +421,7 @@ Fs::Ufs::UFSStoreState::drainWriteQueue()
     if (flags.write_draining)
         return;
 
-    if (!theFile->canWrite())
+    if (!theFile || !theFile->canWrite())
         return;
 
     flags.write_draining = true;

diff --git a/src/fs/ufs/UFSSwapDir.cc b/src/fs/ufs/UFSSwapDir.cc
index 409c2098f1a9bdf7456b67dc8d7cdbc1ad7d77c9..c3603e999129f515a022c3cbe42eb41468d0eed9 100644 (file)
--- a/src/fs/ufs/UFSSwapDir.cc
+++ b/src/fs/ufs/UFSSwapDir.cc
@@ -316,7 +316,8 @@ Fs::Ufs::UFSSwapDir::UFSSwapDir(char const *aType, const char *anIOType) :
     currentIOOptions(new ConfigOptionVector()),
     ioType(xstrdup(anIOType)),
     cur_size(0),
-    n_disk_objects(0)
+    n_disk_objects(0),
+    rebuilding_(false)
 {
     /* modulename is only set to disk modules that are built, by configure,
      * so the Find call should never return NULL here.
@@ -723,6 +724,15 @@ Fs::Ufs::UFSSwapDir::logFile(char const *ext) const
 void
 Fs::Ufs::UFSSwapDir::openLog()
 {
+    assert(NumberOfUFSDirs || !UFSDirToGlobalDirMapping);
+    ++NumberOfUFSDirs;
+    assert(NumberOfUFSDirs <= Config.cacheSwap.n_configured);
+
+    if (rebuilding_) { // we did not close the temporary log used for rebuilding
+        assert(swaplog_fd >= 0);
+        return;
+    }
+
     char *logPath;
     logPath = logFile();
     swaplog_fd = file_open(logPath, O_WRONLY | O_CREAT | O_BINARY);
@@ -733,13 +743,6 @@ Fs::Ufs::UFSSwapDir::openLog()
     }
 
     debugs(50, 3, HERE << "Cache Dir #" << index << " log opened on FD " << swaplog_fd);
-
-    if (0 == NumberOfUFSDirs)
-        assert(NULL == UFSDirToGlobalDirMapping);
-
-    ++NumberOfUFSDirs;
-
-    assert(NumberOfUFSDirs <= Config.cacheSwap.n_configured);
 }
 
 void
@@ -748,18 +751,19 @@ Fs::Ufs::UFSSwapDir::closeLog()
     if (swaplog_fd < 0) /* not open */
         return;
 
+    --NumberOfUFSDirs;
+    assert(NumberOfUFSDirs >= 0);
+    if (!NumberOfUFSDirs)
+        safe_free(UFSDirToGlobalDirMapping);
+
+    if (rebuilding_) // we cannot close the temporary log used for rebuilding
+        return;
+
     file_close(swaplog_fd);
 
     debugs(47, 3, "Cache Dir #" << index << " log closed on FD " << swaplog_fd);
 
     swaplog_fd = -1;
-
-    --NumberOfUFSDirs;
-
-    assert(NumberOfUFSDirs >= 0);
-
-    if (0 == NumberOfUFSDirs)
-        safe_free(UFSDirToGlobalDirMapping);
 }
 
 bool
@@ -839,6 +843,9 @@ Fs::Ufs::UFSSwapDir::rebuild()
 void
 Fs::Ufs::UFSSwapDir::closeTmpSwapLog()
 {
+    assert(rebuilding_);
+    rebuilding_ = false;
+
     char *swaplog_path = xstrdup(logFile(NULL)); // where the swaplog should be
     char *tmp_path = xstrdup(logFile(".new")); // the temporary file we have generated
     int fd;
@@ -864,6 +871,8 @@ Fs::Ufs::UFSSwapDir::closeTmpSwapLog()
 FILE *
 Fs::Ufs::UFSSwapDir::openTmpSwapLog(int *clean_flag, int *zero_flag)
 {
+    assert(!rebuilding_);
+
     char *swaplog_path = xstrdup(logFile(NULL));
     char *clean_path = xstrdup(logFile(".last-clean"));
     char *new_path = xstrdup(logFile(".new"));
@@ -897,6 +906,7 @@ Fs::Ufs::UFSSwapDir::openTmpSwapLog(int *clean_flag, int *zero_flag)
     }
 
     swaplog_fd = fd;
+    rebuilding_ = true;
 
     {
         const StoreSwapLogHeader header;
@@ -1053,18 +1063,17 @@ Fs::Ufs::UFSSwapDir::writeCleanDone()
     cleanLog = NULL;
 }
 
-void
-Fs::Ufs::UFSSwapDir::CleanEvent(void *unused)
+/// safely cleans a few unused files if possible
+int
+Fs::Ufs::UFSSwapDir::HandleCleanEvent()
 {
     static int swap_index = 0;
     int i;
     int j = 0;
     int n = 0;
-    /*
-     * Assert that there are UFS cache_dirs configured, otherwise
-     * we should never be called.
-     */
-    assert(NumberOfUFSDirs);
+
+    if (!NumberOfUFSDirs)
+        return 0; // probably in the middle of reconfiguration
 
     if (NULL == UFSDirToGlobalDirMapping) {
         SwapDir *sd;
@@ -1106,6 +1115,13 @@ Fs::Ufs::UFSSwapDir::CleanEvent(void *unused)
         ++swap_index;
     }
 
+    return n;
+}
+
+void
+Fs::Ufs::UFSSwapDir::CleanEvent(void *)
+{
+    const int n = HandleCleanEvent();
     eventAdd("storeDirClean", CleanEvent, NULL,
              15.0 * exp(-0.25 * n), 1);
 }
@@ -1283,6 +1299,11 @@ Fs::Ufs::UFSSwapDir::search(String const url, HttpRequest *request)
 void
 Fs::Ufs::UFSSwapDir::logEntry(const StoreEntry & e, int op) const
 {
+    if (swaplog_fd < 0) {
+        debugs(36, 5, "cannot log " << e << " in the middle of reconfiguration");
+        return;
+    }
+
     StoreSwapLogData *s = new StoreSwapLogData;
     s->op = (char) op;
     s->swap_filen = e.swap_filen;

diff --git a/src/fs/ufs/UFSSwapDir.h b/src/fs/ufs/UFSSwapDir.h
index 1cea8715f5fb51f220740828959118f3ed901850..af5aa3d454f00c709bc4b40fd1a9c51afe085fcf 100644 (file)
--- a/src/fs/ufs/UFSSwapDir.h
+++ b/src/fs/ufs/UFSSwapDir.h
@@ -145,6 +145,7 @@ private:
     bool pathIsDirectory(const char *path)const;
     int swaplog_fd;
     static EVH CleanEvent;
+    static int HandleCleanEvent();
     /** Verify that the the CacheDir exists
      *
      * If this returns < 0, then Squid exits, complains about swap
@@ -164,6 +165,7 @@ private:
     char const *ioType;
     uint64_t cur_size; ///< currently used space in the storage area
     uint64_t n_disk_objects; ///< total number of objects stored
+    bool rebuilding_; ///< whether RebuildState is writing the new swap.state
 };
 
 } //namespace Ufs