Report IpcIo file name with errors and warnings

to inform admin which cache_dir needs troubleshooting or tuning.

Some level-0/1 messages did not mention disker ID or file name at all while
others relied on disker process ID which is too low-level information from most
admins point of view.

Also improved error and warning messages consistency.

diff --git a/src/DiskIO/IpcIo/IpcIoFile.cc b/src/DiskIO/IpcIo/IpcIoFile.cc
index 6b7a67500a78b24cc51183c481a7c5b7c4fb6616..87902ee893042fd6f05adaa35925141d635ea73d 100644 (file)
--- a/src/DiskIO/IpcIo/IpcIoFile.cc
+++ b/src/DiskIO/IpcIo/IpcIoFile.cc
@@ -140,7 +140,8 @@ IpcIoFile::openCompleted(const Ipc::StrandSearchResponse *const response)
     Must(diskId < 0); // we do not know our disker yet
 
     if (!response) {
-        debugs(79, DBG_IMPORTANT, HERE << "error: timeout");
+        debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " communication " <<
+               "channel establishment timeout");
         error_ = true;
     } else {
         diskId = response->strand.kidId;
@@ -150,7 +151,8 @@ IpcIoFile::openCompleted(const Ipc::StrandSearchResponse *const response)
             Must(inserted);
         } else {
             error_ = true;
-            debugs(79, DBG_IMPORTANT, HERE << "error: no disker claimed " << dbName);
+            debugs(79, DBG_IMPORTANT, "ERROR: no disker claimed " <<
+                   "responsibility for " << dbName);
         }
     }
 
@@ -227,10 +229,12 @@ IpcIoFile::readCompleted(ReadRequest *readRequest,
         ioError = true; // I/O timeout does not warrant setting error_?
     } else {
         if (response->xerrno) {
-            debugs(79, DBG_IMPORTANT, HERE << "error: " << xstrerr(response->xerrno));
+            debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " read: " <<
+                   xstrerr(response->xerrno));
             ioError = error_ = true;
         } else if (!response->page) {
-            debugs(79, DBG_IMPORTANT, HERE << "error: run out of shared memory pages");
+            debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " read ran " <<
+                   "out of shared memory pages");
             ioError = true;
         } else {
             const char *const buf = Ipc::Mem::PagePointer(response->page);
@@ -358,14 +362,15 @@ IpcIoFile::push(IpcIoPendingRequest *const pending)
             Notify(diskId); // must notify disker
         trackPendingRequest(ipcIo.requestId, pending);
     } catch (const Queue::Full &) {
-        debugs(47, DBG_IMPORTANT, "Worker I/O push queue overflow: " <<
+        debugs(47, DBG_IMPORTANT, "ERROR: worker I/O push queue for " <<
+               dbName << " overflow: " <<
                SipcIo(KidIdentifier, ipcIo, diskId)); // TODO: report queue len
         // TODO: grow queue size
 
         pending->completeIo(NULL);
         delete pending;
     } catch (const TextException &e) {
-        debugs(47, DBG_IMPORTANT, HERE << e.what());
+        debugs(47, DBG_IMPORTANT, "ERROR: " << dbName << " exception: " << e.what());
         pending->completeIo(NULL);
         delete pending;
     }
@@ -523,15 +528,15 @@ IpcIoFile::checkTimeouts()
 
     if (timeoutsBefore > timeoutsNow) { // some requests were rescued
         // notification message lost or significantly delayed?
-        debugs(47, DBG_IMPORTANT, "WARNING: communication with disker " <<
-               "may be too slow or disrupted for about " <<
+        debugs(47, DBG_IMPORTANT, "WARNING: communication with " << dbName <<
+               " may be too slow or disrupted for about " <<
                Timeout << "s; rescued " << (timeoutsBefore - timeoutsNow) <<
                " out of " << timeoutsBefore << " I/Os");
     }
 
     if (timeoutsNow) {
         debugs(47, DBG_IMPORTANT, "WARNING: abandoning " <<
-               timeoutsNow << " I/Os after at least " <<
+               timeoutsNow << ' ' << dbName << " I/Os after at least " <<
                Timeout << "s timeout");
     }
 
@@ -631,6 +636,7 @@ IpcIoPendingRequest::completeIo(IpcIoMsg *const response)
 
 /* XXX: disker code that should probably be moved elsewhere */
 
+static String DbName; ///< full db file name
 static int TheFile = -1; ///< db file descriptor
 
 static void
@@ -682,8 +688,8 @@ diskerWriteAttempts(IpcIoMsg &ipcIo)
         if (result < 0) {
             ipcIo.xerrno = errno;
             assert(ipcIo.xerrno);
-            debugs(47, DBG_IMPORTANT,  "disker" << KidIdentifier <<
-                   " error writing " << toWrite << '/' << ipcIo.len <<
+            debugs(47, DBG_IMPORTANT, "ERROR: " << DbName << " failure" <<
+                   " writing " << toWrite << '/' << ipcIo.len <<
                    " at " << ipcIo.offset << '+' << wroteSoFar <<
                    " on " << attempts << " try: " << xstrerr(ipcIo.xerrno));
             ipcIo.len = wroteSoFar;
@@ -712,8 +718,8 @@ diskerWriteAttempts(IpcIoMsg &ipcIo)
         toWrite -= wroteNow;
     }
 
-    debugs(47, DBG_IMPORTANT,  "disker" << KidIdentifier <<
-           " exhausted all " << attemptLimit << " attempts while writing " <<
+    debugs(47, DBG_IMPORTANT, "ERROR: " << DbName << " exhausted all " <<
+           attemptLimit << " attempts while writing " <<
            toWrite << '/' << ipcIo.len << " at " << ipcIo.offset << '+' <<
            wroteSoFar);
     return; // not a fatal I/O error, unless the caller treats it as such
@@ -776,9 +782,9 @@ IpcIoFile::WaitBeforePop()
         const int64_t toSpend = balance - maxImbalance/2;
 
         if (toSpend/1e3 > Timeout)
-            debugs(47, DBG_IMPORTANT, "WARNING: Rock disker delays I/O " <<
-                   "requests for " << (toSpend/1e3) << " seconds to obey " <<
-                   ioRate << "/sec rate limit");
+            debugs(47, DBG_IMPORTANT, "WARNING: " << DbName << " delays " <<
+                   "I/O requests for " << (toSpend/1e3) << " seconds " <<
+                   "to obey " << ioRate << "/sec rate limit");
 
         debugs(47, 3, HERE << "rate limiting by " << toSpend << " ms to get" <<
                (1e3*maxRate) << "/sec rate");
@@ -843,7 +849,7 @@ void
 IpcIoFile::DiskerHandleRequest(const int workerId, IpcIoMsg &ipcIo)
 {
     if (ipcIo.command != IpcIo::cmdRead && ipcIo.command != IpcIo::cmdWrite) {
-        debugs(0, DBG_CRITICAL, HERE << "disker" << KidIdentifier <<
+        debugs(0, DBG_CRITICAL, "ERROR: " << DbName <<
                " should not receive " << ipcIo.command <<
                " ipcIo" << workerId << '.' << ipcIo.requestId);
         return;
@@ -869,7 +875,8 @@ IpcIoFile::DiskerHandleRequest(const int workerId, IpcIoMsg &ipcIo)
         // before push()ing and because if disker pops N requests at a time,
         // we should make sure the worker pop() queue length is the worker
         // push queue length plus N+1. XXX: implement the N+1 difference.
-        debugs(47, DBG_IMPORTANT, "BUG: Worker I/O pop queue overflow: " <<
+        debugs(47, DBG_IMPORTANT, "BUG: Worker I/O pop queue for " <<
+               DbName << " overflow: " <<
                SipcIo(workerId, ipcIo, KidIdentifier)); // TODO: report queue len
 
         // the I/O request we could not push will timeout
@@ -881,17 +888,18 @@ DiskerOpen(const String &path, int flags, mode_t mode)
 {
     assert(TheFile < 0);
 
-    TheFile = file_open(path.termedBuf(), flags);
+    DbName = path;
+    TheFile = file_open(DbName.termedBuf(), flags);
 
     if (TheFile < 0) {
         const int xerrno = errno;
-        debugs(47, DBG_CRITICAL, HERE << "rock db error opening " << path << ": " <<
+        debugs(47, DBG_CRITICAL, "ERROR: cannot open " << DbName << ": " <<
                xstrerr(xerrno));
         return false;
     }
 
     ++store_open_disk_fd;
-    debugs(79,3, HERE << "rock db opened " << path << ": FD " << TheFile);
+    debugs(79,3, HERE << "rock db opened " << DbName << ": FD " << TheFile);
     return true;
 }
 
@@ -904,6 +912,7 @@ DiskerClose(const String &path)
         TheFile = -1;
         --store_open_disk_fd;
     }
+    DbName.clean();
 }
 
 /// reports our needs for shared memory pages to Ipc::Mem::Pages