DAFS: Fix SYNC_FAILED VScheduleSalvage_r log
[openafs.git] / src / vol / volume.c
index 287041e..65af01d 100644 (file)
@@ -479,6 +479,8 @@ VOptDefaults(ProgramType pt, VolumePackageOptions *opts)
     opts->interrupt_rxcall = NULL;
     opts->offline_timeout = -1;
     opts->offline_shutdown_timeout = -1;
+    opts->usage_threshold = 128;
+    opts->usage_rate_limit = 5;
 
 #ifdef FAST_RESTART
     opts->unsafe_attach = 1;
@@ -1877,6 +1879,22 @@ VShutdownVolume_r(Volume * vp)
 /* Header I/O routines                             */
 /***************************************************/
 
+static const char *
+HeaderName(bit32 magic)
+{
+    switch (magic) {
+    case VOLUMEINFOMAGIC:
+       return "volume info";
+    case SMALLINDEXMAGIC:
+       return "small index";
+    case LARGEINDEXMAGIC:
+       return "large index";
+    case LINKTABLEMAGIC:
+       return "link table";
+    }
+    return "unknown";
+}
+
 /* open a descriptor for the inode (h),
  * read in an on-disk structure into buffer (to) of size (size),
  * verify versionstamp in structure has magic (magic) and
@@ -1888,29 +1906,63 @@ ReadHeader(Error * ec, IHandle_t * h, char *to, int size, bit32 magic,
 {
     struct versionStamp *vsn;
     FdHandle_t *fdP;
+    afs_sfsize_t nbytes;
+    afs_ino_str_t stmp;
 
     *ec = 0;
     if (h == NULL) {
+       Log("ReadHeader: Null inode handle argument for %s header file.\n",
+           HeaderName(magic));
        *ec = VSALVAGE;
        return;
     }
 
     fdP = IH_OPEN(h);
     if (fdP == NULL) {
+       Log("ReadHeader: Failed to open %s header file "
+           "(volume=%u, inode=%s); errno=%d\n", HeaderName(magic), h->ih_vid,
+           PrintInode(stmp, h->ih_ino), errno);
        *ec = VSALVAGE;
        return;
     }
 
     vsn = (struct versionStamp *)to;
-    if (FDH_PREAD(fdP, to, size, 0) != size || vsn->magic != magic) {
+    nbytes = FDH_PREAD(fdP, to, size, 0);
+    if (nbytes < 0) {
+       Log("ReadHeader: Failed to read %s header file "
+           "(volume=%u, inode=%s); errno=%d\n", HeaderName(magic), h->ih_vid,
+           PrintInode(stmp, h->ih_ino), errno);
+       *ec = VSALVAGE;
+       FDH_REALLYCLOSE(fdP);
+       return;
+    }
+    if (nbytes != size) {
+       Log("ReadHeader: Incorrect number of bytes read from %s header file "
+           "(volume=%u, inode=%s); expected=%d, read=%d\n",
+           HeaderName(magic), h->ih_vid, PrintInode(stmp, h->ih_ino), size,
+           (int)nbytes);
        *ec = VSALVAGE;
        FDH_REALLYCLOSE(fdP);
        return;
     }
+    if (vsn->magic != magic) {
+       Log("ReadHeader: Incorrect magic for %s header file "
+           "(volume=%u, inode=%s); expected=0x%x, read=0x%x\n",
+           HeaderName(magic), h->ih_vid, PrintInode(stmp, h->ih_ino), magic,
+           vsn->magic);
+       *ec = VSALVAGE;
+       FDH_REALLYCLOSE(fdP);
+       return;
+    }
+
     FDH_CLOSE(fdP);
 
     /* Check is conditional, in case caller wants to inspect version himself */
     if (version && vsn->version != version) {
+       Log("ReadHeader: Incorrect version for %s header file "
+           "(volume=%u, inode=%s); expected=%x, read=%x\n",
+           HeaderName(magic), h->ih_vid, PrintInode(stmp, h->ih_ino),
+           version, vsn->version);
        *ec = VSALVAGE;
     }
 }
@@ -2147,7 +2199,8 @@ VPreAttachVolumeByVp_r(Error * ec,
         *   - volume is in an error state
         *   - volume is pre-attached
         */
-       Log("VPreattachVolumeByVp_r: volume %u not in quiescent state\n", vid);
+       Log("VPreattachVolumeByVp_r: volume %u not in quiescent state (state %u flags 0x%x)\n",
+           vid, V_attachState(vp), V_attachFlags(vp));
        goto done;
     } else if (vp) {
        /* we're re-attaching a volume; clear out some old state */
@@ -3112,7 +3165,8 @@ attach2(Error * ec, VolId volumeId, char *path, struct DiskPartition64 *partp,
     if (*ec == VNOVOL) {
        /* if the volume doesn't exist, skip straight to 'error' so we don't
         * request a salvage */
-       goto unlocked_error;
+       VOL_LOCK;
+       goto error_notbroken;
     }
 
     if (!*ec) {
@@ -3206,7 +3260,8 @@ attach2(Error * ec, VolId volumeId, char *path, struct DiskPartition64 *partp,
        goto locked_error;
     } else if (*ec) {
        /* volume operation in progress */
-       goto unlocked_error;
+       VOL_LOCK;
+       goto error_notbroken;
     }
 #else /* AFS_DEMAND_ATTACH_FS */
     if (*ec) {
@@ -3405,11 +3460,18 @@ attach2(Error * ec, VolId volumeId, char *path, struct DiskPartition64 *partp,
 
     return vp;
 
+#ifndef AFS_DEMAND_ATTACH_FS
 unlocked_error:
+#endif
+
     VOL_LOCK;
 locked_error:
 #ifdef AFS_DEMAND_ATTACH_FS
     if (!VIsErrorState(V_attachState(vp))) {
+       if (VIsErrorState(error_state)) {
+           Log("attach2: forcing vol %u to error state (state %u flags 0x%x ec %d)\n",
+               vp->hashid, V_attachState(vp), V_attachFlags(vp), *ec);
+       }
        VChangeState_r(vp, error_state);
     }
 #endif /* AFS_DEMAND_ATTACH_FS */
@@ -3418,6 +3480,7 @@ locked_error:
        VReleaseVolumeHandles_r(vp);
     }
 
+ error_notbroken:
 #ifdef AFS_DEMAND_ATTACH_FS
     VCheckSalvage(vp);
     if (forcefree) {
@@ -4077,9 +4140,17 @@ GetVolume(Error * ec, Error * client_ec, VolId volumeId, Volume * hint,
            vp = NULL;
            break;
        }
-#endif
 
-#ifdef AFS_DEMAND_ATTACH_FS
+       if (VIsErrorState(V_attachState(vp))) {
+           /* make sure we don't take a vp in VOL_STATE_ERROR state and use
+            * it, or transition it out of that state */
+           if (!*ec) {
+               *ec = VNOVOL;
+           }
+           vp = NULL;
+           break;
+       }
+
        /*
         * this test MUST happen after VAttachVolymeByVp, so vol_op_state is
         * not VolOpRunningUnknown (attach2 would have converted it to Online
@@ -5779,6 +5850,10 @@ VScheduleSalvage_r(Volume * vp)
                Log("VScheduleSalvage_r: Salvage request for volume %lu "
                    "denied\n", afs_printable_uint32_lu(vp->hashid));
                break;
+           case SYNC_FAILED:
+               Log("VScheduleSalvage_r: Salvage request for volume %lu "
+                   "failed\n", afs_printable_uint32_lu(vp->hashid));
+               break;
            default:
                Log("VScheduleSalvage_r: Salvage request for volume %lu "
                    "received unknown protocol error %d\n",
@@ -6674,10 +6749,16 @@ VBumpVolumeUsage_r(Volume * vp)
     if (now - V_dayUseDate(vp) > OneDay)
        VAdjustVolumeStatistics_r(vp);
     /*
-     * Save the volume header image to disk after every 128 bumps to dayUse.
+     * Save the volume header image to disk after a threshold of bumps to dayUse,
+     * at most every usage_rate_limit seconds.
      */
-    if ((V_dayUse(vp)++ & 127) == 0) {
+    V_dayUse(vp)++;
+    vp->usage_bumps_outstanding++;
+    if (vp->usage_bumps_outstanding >= vol_opts.usage_threshold
+       && vp->usage_bumps_next_write <= now) {
        Error error;
+       vp->usage_bumps_outstanding = 0;
+       vp->usage_bumps_next_write = now + vol_opts.usage_rate_limit;
        VUpdateVolume_r(&error, vp, VOL_UPDATE_WAIT);
     }
 }
@@ -7929,7 +8010,7 @@ GetVolHeaderFromLRU(void)
      * could VWaitExclusiveState_r instead, but not waiting is faster and
      * easier to do */
     for (queue_Scan(&volume_hdr_LRU, qh, nqh, volHeader)) {
-       if (!hd->back || !VIsExclusiveState(V_attachState(hd->back))) {
+       if (!qh->back || !VIsExclusiveState(V_attachState(qh->back))) {
            queue_Remove(qh);
            hd = qh;
            break;