viced: Restore some previous log message language
[openafs.git] / src / viced / afsfileprocs.c
index 0bb0ea3..76e7ff1 100644 (file)
@@ -76,6 +76,7 @@
 #include <afs/opr.h>
 #include <rx/rx_queue.h>
 #include <opr/lock.h>
+#include <opr/proc.h>
 #include <afs/nfs.h>
 #include <afs/afsint.h>
 #include <afs/vldbint.h>
@@ -245,7 +246,7 @@ SetVolumeSync(struct AFSVolSync *async, Volume * avol)
     /* date volume instance was created */
     if (async) {
        if (avol)
-           async->spare1 = avol->header->diskstuff.creationDate;
+           async->spare1 = V_creationDate(avol);
        else
            async->spare1 = 0;
        async->spare2 = 0;
@@ -283,8 +284,8 @@ CheckLength(struct Volume *vp, struct Vnode *vnp, afs_sfsize_t alen)
 
        fdP = IH_OPEN(vnp->handle);
        if (fdP == NULL) {
-           ViceLog(0, ("CheckLength: cannot open inode for fid %lu.%lu.%lu\n",
-                       afs_printable_uint32_lu(vp->hashid),
+           ViceLog(0, ("CheckLength: cannot open inode for fid %" AFS_VOLID_FMT ".%lu.%lu\n",
+                       afs_printable_VolumeId_lu(vp->hashid),
                        afs_printable_uint32_lu(Vn_id(vnp)),
                        afs_printable_uint32_lu(vnp->disk.uniquifier)));
            return -1;
@@ -293,9 +294,9 @@ CheckLength(struct Volume *vp, struct Vnode *vnp, afs_sfsize_t alen)
        FDH_CLOSE(fdP);
        if (alen < 0) {
            afs_int64 alen64 = alen;
-           ViceLog(0, ("CheckLength: cannot get size for inode for fid "
-                       "%lu.%lu.%lu; FDH_SIZE returned %" AFS_INT64_FMT "\n",
-                       afs_printable_uint32_lu(vp->hashid),
+           ViceLog(0, ("CheckLength: cannot get size for inode for fid %"
+                       AFS_VOLID_FMT ".%lu.%lu; FDH_SIZE returned %" AFS_INT64_FMT "\n",
+                       afs_printable_VolumeId_lu(vp->hashid),
                        afs_printable_uint32_lu(Vn_id(vnp)),
                        afs_printable_uint32_lu(vnp->disk.uniquifier),
                        alen64));
@@ -305,9 +306,9 @@ CheckLength(struct Volume *vp, struct Vnode *vnp, afs_sfsize_t alen)
 
     if (alen != vlen) {
        afs_int64 alen64 = alen, vlen64 = vlen;
-       ViceLog(0, ("Fid %lu.%lu.%lu has inconsistent length (index "
+       ViceLog(0, ("Fid %" AFS_VOLID_FMT ".%lu.%lu has inconsistent length (index "
                    "%lld inode %lld ); volume must be salvaged\n",
-                   afs_printable_uint32_lu(vp->hashid),
+                   afs_printable_VolumeId_lu(vp->hashid),
                    afs_printable_uint32_lu(Vn_id(vnp)),
                    afs_printable_uint32_lu(vnp->disk.uniquifier),
                    vlen64, alen64));
@@ -316,17 +317,44 @@ CheckLength(struct Volume *vp, struct Vnode *vnp, afs_sfsize_t alen)
     return 0;
 }
 
+static void
+LogClientError(const char *message, struct rx_connection *tcon, afs_int32 viceid, struct AFSFid *Fid)
+{
+    char hoststr[16];
+    if (Fid) {
+       ViceLog(0, ("%s while handling request from host %s:%d viceid %d "
+                   "fid %" AFS_VOLID_FMT ".%lu.%lu, failing request\n",
+                   message,
+                   afs_inet_ntoa_r(rx_HostOf(rx_PeerOf(tcon)), hoststr),
+                   (int)ntohs(rx_PortOf(rx_PeerOf(tcon))),
+                   viceid,
+                   afs_printable_VolumeId_lu(Fid->Volume),
+                   afs_printable_uint32_lu(Fid->Vnode),
+                   afs_printable_uint32_lu(Fid->Unique)));
+    } else {
+       ViceLog(0, ("%s while handling request from host %s:%d viceid %d "
+                   "fid (none), failing request\n",
+                   message,
+                   afs_inet_ntoa_r(rx_HostOf(rx_PeerOf(tcon)), hoststr),
+                   (int)ntohs(rx_PortOf(rx_PeerOf(tcon))),
+                   viceid));
+    }
+}
+
 /*
  * Note that this function always returns a held host, so
  * that CallPostamble can block without the host's disappearing.
  * Call returns rx connection in passed in *tconn
+ *
+ * 'Fid' is optional, and is just used for printing log messages.
  */
 static int
-CallPreamble(struct rx_call *acall, int activecall,
+CallPreamble(struct rx_call *acall, int activecall, struct AFSFid *Fid,
             struct rx_connection **tconn, struct host **ahostp)
 {
     struct host *thost;
     struct client *tclient;
+    afs_int32 viceid = -1;
     int retry_flag = 1;
     int code = 0;
     char hoststr[16], hoststr2[16];
@@ -341,10 +369,10 @@ CallPreamble(struct rx_call *acall, int activecall,
 
     H_LOCK;
   retry:
-    tclient = h_FindClient_r(*tconn);
+    tclient = h_FindClient_r(*tconn, &viceid);
     if (!tclient) {
-       ViceLog(0, ("CallPreamble: Couldn't get client.\n"));
        H_UNLOCK;
+       LogClientError("CallPreamble: Couldn't get client", *tconn, viceid, Fid);
        return VBUSY;
     }
     thost = tclient->host;
@@ -352,8 +380,8 @@ CallPreamble(struct rx_call *acall, int activecall,
        if (!retry_flag) {
            h_ReleaseClient_r(tclient);
            h_Release_r(thost);
-           ViceLog(0, ("CallPreamble: Couldn't get CPS. Fail\n"));
            H_UNLOCK;
+           LogClientError("CallPreamble: Couldn't get CPS", *tconn, viceid, Fid);
            return -1001;
        }
        retry_flag = 0;         /* Retry once */
@@ -380,7 +408,7 @@ CallPreamble(struct rx_call *acall, int activecall,
            h_ReleaseClient_r(tclient);
            h_Release_r(thost);
            H_UNLOCK;
-           ViceLog(0, ("CallPreamble: couldn't reconnect to ptserver\n"));
+           LogClientError("CallPreamble: couldn't reconnect to ptserver", *tconn, viceid, Fid);
            return -1001;
        }
 
@@ -449,7 +477,7 @@ CallPostamble(struct rx_connection *aconn, afs_int32 ret,
     int translate = 0;
 
     H_LOCK;
-    tclient = h_FindClient_r(aconn);
+    tclient = h_FindClient_r(aconn, NULL);
     if (!tclient)
        goto busyout;
     thost = tclient->host;
@@ -811,7 +839,7 @@ GetVolumePackageWithCall(struct rx_call *acall, struct VCallByVol *cbv,
                         struct client **client, int locktype,
                         afs_int32 * rights, afs_int32 * anyrights, int remote)
 {
-    struct acl_accessList *aCL;        /* Internal access List */
+    struct acl_accessList *aCL = NULL; /* Internal access List */
     int aCLSize;               /* size of the access list */
     Error errorCode = 0;               /* return code to caller */
     struct rx_connection *tcon = rx_ConnectionOf(acall);
@@ -1220,6 +1248,26 @@ RXStore_AccessList(Vnode * targetptr, struct AFSOpaque *AccessList)
 
 }                              /*RXStore_AccessList */
 
+static int
+CheckLink(Volume *volptr, FdHandle_t *fdP, const char *descr)
+{
+    int code;
+    afs_ino_str_t ino;
+
+    code = FDH_ISUNLINKED(fdP);
+    if (code < 0) {
+       ViceLog(0, ("CopyOnWrite: error fstating volume %u inode %s (%s), errno %d\n",
+                   V_id(volptr), PrintInode(ino, fdP->fd_ih->ih_ino), descr, errno));
+       return -1;
+    }
+    if (code) {
+       ViceLog(0, ("CopyOnWrite corruption prevention: detected zero nlink for "
+                   "volume %u inode %s (%s), forcing volume offline\n",
+                   V_id(volptr), PrintInode(ino, fdP->fd_ih->ih_ino), descr));
+       return -1;
+    }
+    return 0;
+}
 
 /* In our current implementation, each successive data store (new file
  * data version) creates a new inode. This function creates the new
@@ -1266,16 +1314,16 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
     if (!VALID_INO(ino)) {
        free(buff);
        VTakeOffline(volptr);
-       ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                   volptr->hashid));
+       ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                   afs_printable_VolumeId_lu(volptr->hashid)));
        return EIO;
     }
     targFdP = IH_OPEN(targetptr->handle);
     if (targFdP == NULL) {
        rc = errno;
        ViceLog(0,
-               ("CopyOnWrite failed: Failed to open target vnode %u in volume %u (errno = %d)\n",
-                targetptr->vnodeNumber, V_id(volptr), rc));
+               ("CopyOnWrite failed: Failed to open target vnode %u in volume %" AFS_VOLID_FMT " (errno = %d)\n",
+                targetptr->vnodeNumber, afs_printable_VolumeId_lu(V_id(volptr)), rc));
        free(buff);
        VTakeOffline(volptr);
        return rc;
@@ -1290,8 +1338,8 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
                  (int)targetptr->disk.dataVersion);
     if (!VALID_INO(ino)) {
        ViceLog(0,
-               ("CopyOnWrite failed: Partition %s that contains volume %u may be out of free inodes(errno = %d)\n",
-                volptr->partition->name, V_id(volptr), errno));
+               ("CopyOnWrite failed: Partition %s that contains volume %" AFS_VOLID_FMT " may be out of free inodes(errno = %d)\n",
+                volptr->partition->name, afs_printable_VolumeId_lu(V_id(volptr)), errno));
        FDH_CLOSE(targFdP);
        free(buff);
        return ENOSPC;
@@ -1300,6 +1348,20 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
     newFdP = IH_OPEN(newH);
     opr_Assert(newFdP != NULL);
 
+    rc = CheckLink(volptr, targFdP, "source");
+    if (!rc) {
+       rc = CheckLink(volptr, newFdP, "dest");
+    }
+    if (rc) {
+       FDH_REALLYCLOSE(newFdP);
+       IH_RELEASE(newH);
+       FDH_REALLYCLOSE(targFdP);
+       IH_DEC(V_linkHandle(volptr), ino, V_parentId(volptr));
+       free(buff);
+       VTakeOffline(volptr);
+       return VSALVAGE;
+    }
+
     done = off;
     while (size > 0) {
        if (size > COPYBUFFSIZE) {      /* more than a buffer */
@@ -1327,8 +1389,8 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
        if ((rdlen != length) || (wrlen != length)) {
            if ((wrlen < 0) && (errno == ENOSPC)) {     /* disk full */
                ViceLog(0,
-                       ("CopyOnWrite failed: Partition %s containing volume %u is full\n",
-                        volptr->partition->name, V_id(volptr)));
+                       ("CopyOnWrite failed: Partition %s containing volume %" AFS_VOLID_FMT " is full\n",
+                        volptr->partition->name, afs_printable_VolumeId_lu(V_id(volptr))));
                /* remove destination inode which was partially copied till now */
                FDH_REALLYCLOSE(newFdP);
                IH_RELEASE(newH);
@@ -1336,8 +1398,8 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
                rc = IH_DEC(V_linkHandle(volptr), ino, V_parentId(volptr));
                if (rc) {
                    ViceLog(0,
-                           ("CopyOnWrite failed: error %u after i_dec on disk full, volume %u in partition %s needs salvage\n",
-                            rc, V_id(volptr), volptr->partition->name));
+                           ("CopyOnWrite failed: error %u after i_dec on disk full, volume %" AFS_VOLID_FMT " in partition %s needs salvage\n",
+                            rc, afs_printable_VolumeId_lu(V_id(volptr)), volptr->partition->name));
                    VTakeOffline(volptr);
                }
                free(buff);
@@ -1348,8 +1410,8 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
                 * time, just case to an unsigned int for printing */
 
                ViceLog(0,
-                       ("CopyOnWrite failed: volume %u in partition %s  (tried reading %u, read %u, wrote %u, errno %u) volume needs salvage\n",
-                        V_id(volptr), volptr->partition->name, (unsigned)length, (unsigned)rdlen,
+                       ("CopyOnWrite failed: volume %" AFS_VOLID_FMT " in partition %s  (tried reading %u, read %u, wrote %u, errno %u) volume needs salvage\n",
+                        afs_printable_VolumeId_lu(V_id(volptr)), volptr->partition->name, (unsigned)length, (unsigned)rdlen,
                         (unsigned)wrlen, errno));
 #if defined(AFS_DEMAND_ATTACH_FS)
                ViceLog(0, ("CopyOnWrite failed: requesting salvage\n"));
@@ -1360,7 +1422,7 @@ CopyOnWrite(Vnode * targetptr, Volume * volptr, afs_foff_t off, afs_fsize_t len)
                FDH_REALLYCLOSE(newFdP);
                IH_RELEASE(newH);
                FDH_REALLYCLOSE(targFdP);
-               rc = IH_DEC(V_linkHandle(volptr), ino, V_parentId(volptr));
+               IH_DEC(V_linkHandle(volptr), ino, V_parentId(volptr));
                free(buff);
                VTakeOffline(volptr);
                return EIO;
@@ -1447,8 +1509,8 @@ DeleteTarget(Vnode * parentptr, Volume * volptr, Vnode ** targetptr,
     if ((*targetptr)->disk.uniquifier != fileFid->Unique) {
        VTakeOffline(volptr);
        ViceLog(0,
-               ("Volume %u now offline, must be salvaged.\n",
-                volptr->hashid));
+               ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                afs_printable_VolumeId_lu(volptr->hashid)));
        errorCode = VSALVAGE;
        return errorCode;
     }
@@ -1479,8 +1541,8 @@ DeleteTarget(Vnode * parentptr, Volume * volptr, Vnode ** targetptr,
                {
                    VTakeOffline(volptr);
                    ViceLog(0,
-                           ("Volume %u now offline, must be salvaged.\n",
-                            volptr->hashid));
+                           ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                            afs_printable_VolumeId_lu(volptr->hashid)));
                    return (EIO);
                }
                DT1++;
@@ -1505,8 +1567,8 @@ DeleteTarget(Vnode * parentptr, Volume * volptr, Vnode ** targetptr,
                   Directory) ? "directory" : "file")));
        VTakeOffline(volptr);
        ViceLog(0,
-               ("Volume %u now offline, must be salvaged.\n",
-                volptr->hashid));
+               ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                afs_printable_VolumeId_lu(volptr->hashid)));
        if (!errorCode)
            errorCode = code;
     }
@@ -1667,9 +1729,11 @@ Update_TargetVnodeStatus(Vnode * targetptr, afs_uint32 Caller,
     if (Caller & TVS_SDATA) {
        targetptr->disk.dataVersion++;
        if (!remote && VanillaUser(client)) {
-           targetptr->disk.modeBits &= ~04000; /* turn off suid for file. */
+           /* turn off suid */
+           targetptr->disk.modeBits = targetptr->disk.modeBits & ~04000;
 #ifdef CREATE_SGUID_ADMIN_ONLY
-           targetptr->disk.modeBits &= ~02000; /* turn off sgid for file. */
+           /* turn off sgid */
+           targetptr->disk.modeBits = targetptr->disk.modeBits & ~02000;
 #endif
        }
     }
@@ -1685,9 +1749,11 @@ Update_TargetVnodeStatus(Vnode * targetptr, afs_uint32 Caller,
     if (InStatus->Mask & AFS_SETOWNER) {
        /* admin is allowed to do chmod, chown as well as chown, chmod. */
        if (!remote && VanillaUser(client)) {
-           targetptr->disk.modeBits &= ~04000; /* turn off suid for file. */
+           /* turn off suid */
+           targetptr->disk.modeBits = targetptr->disk.modeBits & ~04000;
 #ifdef CREATE_SGUID_ADMIN_ONLY
-           targetptr->disk.modeBits &= ~02000; /* turn off sgid for file. */
+           /* turn off sgid */
+           targetptr->disk.modeBits = targetptr->disk.modeBits & ~02000;
 #endif
        }
        targetptr->disk.owner = InStatus->Owner;
@@ -1771,14 +1837,16 @@ AdjustDiskUsage(Volume * volptr, afs_sfsize_t length,
        VAdjustDiskUsage(&nc, volptr, -length, 0);
        if (rc == VOVERQUOTA) {
            ViceLog(2,
-                   ("Volume %u (%s) is full\n", V_id(volptr),
+                   ("Volume %" AFS_VOLID_FMT " (%s) is full\n",
+                    afs_printable_VolumeId_lu(V_id(volptr)),
                     V_name(volptr)));
            return (rc);
        }
        if (rc == VDISKFULL) {
            ViceLog(0,
-                   ("Partition %s that contains volume %u is full\n",
-                    volptr->partition->name, V_id(volptr)));
+                   ("Partition %s that contains volume %" AFS_VOLID_FMT " is full\n",
+                    volptr->partition->name,
+                    afs_printable_VolumeId_lu(V_id(volptr))));
            return (rc);
        }
        ViceLog(0, ("Got error return %d from VAdjustDiskUsage\n", rc));
@@ -1839,8 +1907,8 @@ Alloc_NewVnode(Vnode * parentptr, DirHandle * dir, Volume * volptr,
     /* error in creating inode */
     if (!VALID_INO(inode)) {
        ViceLog(0,
-               ("Volume : %u vnode = %u Failed to create inode: errno = %d\n",
-                (*targetptr)->volumePtr->header->diskstuff.id,
+               ("Volume : %" AFS_VOLID_FMT " vnode = %u Failed to create inode: errno = %d\n",
+                afs_printable_VolumeId_lu(V_id((*targetptr)->volumePtr)),
                 (*targetptr)->vnodeNumber, errno));
        VAdjustDiskUsage(&temp, volptr, -BlocksPreallocatedForVnode, 0);
        (*targetptr)->delete = 1;       /* delete vnode */
@@ -2213,7 +2281,7 @@ common_FetchData64(struct rx_call *acall, struct AFSFid *Fid,
     FS_LOCK;
     AFSCallStats.FetchData++, AFSCallStats.TotalCalls++;
     FS_UNLOCK;
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_FetchData;
 
     /* Get ptr to client data for user Id for logging */
@@ -2365,7 +2433,7 @@ SRXAFS_FetchACL(struct rx_call * acall, struct AFSFid * Fid,
     FS_LOCK;
     AFSCallStats.FetchACL++, AFSCallStats.TotalCalls++;
     FS_UNLOCK;
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_FetchACL;
 
     /* Get ptr to client data for user Id for logging */
@@ -2549,10 +2617,11 @@ SRXAFS_BulkStatus(struct rx_call * acall, struct AFSCBFids * Fids,
     }
     CallBacks->AFSCBs_len = nfiles;
 
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    tfid = Fids->AFSCBFids_val;
+
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, tfid, &tcon, &thost)))
        goto Bad_BulkStatus;
 
-    tfid = Fids->AFSCBFids_val;
     for (i = 0; i < nfiles; i++, tfid++) {
        /*
         * Get volume/vnode for the fetched file; caller's rights to it
@@ -2674,11 +2743,12 @@ SRXAFS_InlineBulkStatus(struct rx_call * acall, struct AFSCBFids * Fids,
     /* Zero out return values to avoid leaking information on partial succes */
     memset(Sync, 0, sizeof(*Sync));
 
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost))) {
+    tfid = Fids->AFSCBFids_val;
+
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, tfid, &tcon, &thost))) {
        goto Bad_InlineBulkStatus;
     }
 
-    tfid = Fids->AFSCBFids_val;
     for (i = 0; i < nfiles; i++, tfid++) {
        /*
         * Get volume/vnode for the fetched file; caller's rights to it
@@ -2797,7 +2867,7 @@ SRXAFS_FetchStatus(struct rx_call * acall, struct AFSFid * Fid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_FETCHSTATUS);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_FetchStatus;
 
     code = SAFSS_FetchStatus(acall, Fid, OutStatus, CallBack, Sync);
@@ -2849,7 +2919,7 @@ common_StoreData64(struct rx_call *acall, struct AFSFid *Fid,
     FS_LOCK;
     AFSCallStats.StoreData++, AFSCallStats.TotalCalls++;
     FS_UNLOCK;
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_StoreData;
 
     /* Get ptr to client data for user Id for logging */
@@ -2997,7 +3067,7 @@ SRXAFS_StoreACL(struct rx_call * acall, struct AFSFid * Fid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_STOREACL);
 
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_StoreACL;
 
     /* Get ptr to client data for user Id for logging */
@@ -3169,7 +3239,7 @@ SRXAFS_StoreStatus(struct rx_call * acall, struct AFSFid * Fid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_STORESTATUS);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_StoreStatus;
 
     code = SAFSS_StoreStatus(acall, Fid, InStatus, OutStatus, Sync);
@@ -3301,7 +3371,7 @@ SRXAFS_RemoveFile(struct rx_call * acall, struct AFSFid * DirFid, char *Name,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_REMOVEFILE);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_RemoveFile;
 
     code = SAFSS_RemoveFile(acall, DirFid, Name, OutDirStatus, Sync);
@@ -3439,7 +3509,7 @@ SRXAFS_CreateFile(struct rx_call * acall, struct AFSFid * DirFid, char *Name,
 
     memset(OutFid, 0, sizeof(struct AFSFid));
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_CreateFile;
 
     code =
@@ -3736,8 +3806,8 @@ SAFSS_Rename(struct rx_call *acall, struct AFSFid *OldDirFid, char *OldName,
            if ((top == 1) && (testnode != 0)) {
                VTakeOffline(volptr);
                ViceLog(0,
-                       ("Volume %u now offline, must be salvaged.\n",
-                        volptr->hashid));
+                       ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                        afs_printable_VolumeId_lu(volptr->hashid)));
                errorCode = EIO;
                goto Bad_Rename;
            }
@@ -3943,7 +4013,7 @@ SRXAFS_Rename(struct rx_call * acall, struct AFSFid * OldDirFid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_RENAME);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, OldDirFid, &tcon, &thost)))
        goto Bad_Rename;
 
     code =
@@ -4068,8 +4138,8 @@ SAFSS_Symlink(struct rx_call *acall, struct AFSFid *DirFid, char *Name,
        (void)PutVolumePackage(acall, parentwhentargetnotdir, targetptr,
                               parentptr, volptr, &client);
        VTakeOffline(volptr);
-       ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                   volptr->hashid));
+       ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                   afs_printable_VolumeId_lu(volptr->hashid)));
        return EIO;
     }
     len = strlen((char *) LinkContents);
@@ -4123,7 +4193,7 @@ SRXAFS_Symlink(struct rx_call *acall,     /* Rx call */
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_SYMLINK);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_Symlink;
 
     code =
@@ -4300,7 +4370,7 @@ SRXAFS_Link(struct rx_call * acall, struct AFSFid * DirFid, char *Name,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_LINK);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_Link;
 
     code =
@@ -4470,7 +4540,7 @@ SRXAFS_MakeDir(struct rx_call * acall, struct AFSFid * DirFid, char *Name,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_MAKEDIR);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_MakeDir;
 
     code =
@@ -4600,7 +4670,7 @@ SRXAFS_RemoveDir(struct rx_call * acall, struct AFSFid * DirFid, char *Name,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_REMOVEDIR);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, DirFid, &tcon, &thost)))
        goto Bad_RemoveDir;
 
     code = SAFSS_RemoveDir(acall, DirFid, Name, OutDirStatus, Sync);
@@ -4704,7 +4774,7 @@ SRXAFS_SetLock(struct rx_call * acall, struct AFSFid * Fid, ViceLockType type,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_SETLOCK);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_SetLock;
 
     code = SAFSS_SetLock(acall, Fid, type, Sync);
@@ -4802,7 +4872,7 @@ SRXAFS_ExtendLock(struct rx_call * acall, struct AFSFid * Fid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_EXTENDLOCK);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_ExtendLock;
 
     code = SAFSS_ExtendLock(acall, Fid, Sync);
@@ -4911,7 +4981,7 @@ SRXAFS_ReleaseLock(struct rx_call * acall, struct AFSFid * Fid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_RELEASELOCK);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, Fid, &tcon, &thost)))
        goto Bad_ReleaseLock;
 
     code = SAFSS_ReleaseLock(acall, Fid, Sync);
@@ -4970,11 +5040,7 @@ SetAFSStats(struct AFSStatistics *stats)
     if (seconds <= 0)
        seconds = 1;
     stats->StoreDataRate = AFSCallStats.TotalStoredBytes / seconds;
-#ifdef AFS_NT40_ENV
-    stats->ProcessSize = -1;   /* TODO: */
-#else
-    stats->ProcessSize = (afs_int32) ((long)sbrk(0) >> 10);
-#endif
+    stats->ProcessSize = opr_procsize();
     FS_UNLOCK;
     h_GetWorkStats((int *)&(stats->WorkStations),
                   (int *)&(stats->ActiveWorkStations), (int *)0,
@@ -5015,7 +5081,7 @@ SRXAFS_GetStatistics(struct rx_call *acall, struct ViceStatistics *Statistics)
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_GETSTATISTICS);
 
-    if ((code = CallPreamble(acall, NOTACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, NOTACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetStatistics;
 
     ViceLog(1, ("SAFS_GetStatistics Received\n"));
@@ -5053,12 +5119,12 @@ SRXAFS_GetStatistics64(struct rx_call *acall, afs_int32 statsVersion, ViceStatis
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_GETSTATISTICS);
 
-    if ((code = CallPreamble(acall, NOTACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, NOTACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetStatistics64;
 
     ViceLog(1, ("SAFS_GetStatistics64 Received\n"));
     Statistics->ViceStatistics64_val =
-       malloc(statsVersion*sizeof(afs_int64));
+       malloc(statsVersion*sizeof(afs_uint64));
     Statistics->ViceStatistics64_len = statsVersion;
     FS_LOCK;
     AFSCallStats.GetStatistics++, AFSCallStats.TotalCalls++;
@@ -5091,12 +5157,7 @@ SRXAFS_GetStatistics64(struct rx_call *acall, afs_int32 statsVersion, ViceStatis
         seconds = 1;
     Statistics->ViceStatistics64_val[STATS64_STOREDATARATE] =
        AFSCallStats.TotalStoredBytes / seconds;
-#ifdef AFS_NT40_ENV
-    Statistics->ViceStatistics64_val[STATS64_PROCESSSIZE] = -1;
-#else
-    Statistics->ViceStatistics64_val[STATS64_PROCESSSIZE] =
-       (afs_int32) ((long)sbrk(0) >> 10);
-#endif
+    Statistics->ViceStatistics64_val[STATS64_PROCESSSIZE] = opr_procsize();
     FS_UNLOCK;
     h_GetWorkStats64(&(Statistics->ViceStatistics64_val[STATS64_WORKSTATIONS]),
                      &(Statistics->ViceStatistics64_val[STATS64_ACTIVEWORKSTATIONS]),
@@ -5492,7 +5553,7 @@ common_GiveUpCallBacks(struct rx_call *acall, struct AFSCBFids *FidArray,
     FS_LOCK;
     AFSCallStats.GiveUpCallBacks++, AFSCallStats.TotalCalls++;
     FS_UNLOCK;
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GiveUpCallBacks;
 
     if (!FidArray && !CallBackArray) {
@@ -5591,7 +5652,7 @@ SRXAFS_GetCapabilities(struct rx_call * acall, Capabilities * capabilities)
     FS_UNLOCK;
     ViceLog(2, ("SAFS_GetCapabilties\n"));
 
-    if ((code = CallPreamble(acall, NOTACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, NOTACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetCaps;
 
     dataBytes = 1 * sizeof(afs_int32);
@@ -5608,7 +5669,7 @@ SRXAFS_GetCapabilities(struct rx_call * acall, Capabilities * capabilities)
     code = CallPostamble(tcon, code, thost);
 
 
-    return 0;
+    return code;
 }
 
 /* client is held, but not locked */
@@ -5809,7 +5870,7 @@ SRXAFS_GetVolumeInfo(struct rx_call * acall, char *avolid,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_GETVOLUMEINFO);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetVolumeInfo;
 
     FS_LOCK;
@@ -5852,7 +5913,7 @@ SRXAFS_GetVolumeStatus(struct rx_call * acall, afs_int32 avolid,
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_GETVOLUMESTATUS);
 
     ViceLog(1, ("SAFS_GetVolumeStatus for volume %u\n", avolid));
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetVolumeStatus;
 
     FS_LOCK;
@@ -5924,7 +5985,7 @@ SRXAFS_SetVolumeStatus(struct rx_call * acall, afs_int32 avolid,
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_SETVOLUMESTATUS);
 
     ViceLog(1, ("SAFS_SetVolumeStatus for volume %u\n", avolid));
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_SetVolumeStatus;
 
     FS_LOCK;
@@ -5991,7 +6052,7 @@ SRXAFS_GetRootVolume(struct rx_call * acall, char **VolumeName)
     return FSERR_EOPNOTSUPP;
 
 #ifdef notdef
-    if (errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &thost))
+    if (errorCode = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost))
        goto Bad_GetRootVolume;
     FS_LOCK;
     AFSCallStats.GetRootVolume++, AFSCallStats.TotalCalls++;
@@ -6042,7 +6103,7 @@ SRXAFS_CheckToken(struct rx_call * acall, afs_int32 AfsId,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_CHECKTOKEN);
 
-    if ((code = CallPreamble(acall, ACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_CheckToken;
 
     code = FSERR_ECONNREFUSED;
@@ -6068,7 +6129,7 @@ SRXAFS_GetTime(struct rx_call * acall, afs_uint32 * Seconds,
 
     fsstats_StartOp(&fsstats, FS_STATS_RPCIDX_GETTIME);
 
-    if ((code = CallPreamble(acall, NOTACTIVECALL, &tcon, &thost)))
+    if ((code = CallPreamble(acall, NOTACTIVECALL, NULL, &tcon, &thost)))
        goto Bad_GetTime;
 
     FS_LOCK;
@@ -6153,8 +6214,8 @@ FetchData_RXStyle(Volume * volptr, Vnode * targetptr,
     fdP = IH_OPEN(ihP);
     if (fdP == NULL) {
        VTakeOffline(volptr);
-       ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                   volptr->hashid));
+       ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                   afs_printable_VolumeId_lu(volptr->hashid)));
        return EIO;
     }
     optSize = sendBufSize;
@@ -6164,8 +6225,8 @@ FetchData_RXStyle(Volume * volptr, Vnode * targetptr,
     if (tlen < 0) {
        FDH_CLOSE(fdP);
        VTakeOffline(volptr);
-       ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                   volptr->hashid));
+       ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                   afs_printable_VolumeId_lu(volptr->hashid)));
        return EIO;
     }
     if (CheckLength(volptr, targetptr, tlen)) {
@@ -6208,8 +6269,8 @@ FetchData_RXStyle(Volume * volptr, Vnode * targetptr,
            FDH_CLOSE(fdP);
            FreeSendBuffer((struct afs_buffer *)tbuffer);
            VTakeOffline(volptr);
-           ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                       volptr->hashid));
+           ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                       afs_printable_VolumeId_lu(volptr->hashid)));
            return EIO;
        }
        nBytes = rx_Write(Call, tbuffer, wlen);
@@ -6224,8 +6285,8 @@ FetchData_RXStyle(Volume * volptr, Vnode * targetptr,
        if (nBytes != wlen) {
            FDH_CLOSE(fdP);
            VTakeOffline(volptr);
-           ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                       volptr->hashid));
+           ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                       afs_printable_VolumeId_lu(volptr->hashid)));
            return EIO;
        }
        nBytes = rx_Writev(Call, tiov, tnio, wlen);
@@ -6393,8 +6454,8 @@ StoreData_RXStyle(Volume * volptr, Vnode * targetptr, struct AFSFid * Fid,
        if (GetLinkCountAndSize(volptr, fdP, &linkCount, &DataLength) < 0) {
            FDH_CLOSE(fdP);
            VTakeOffline(volptr);
-           ViceLog(0, ("Volume %u now offline, must be salvaged.\n",
-                       volptr->hashid));
+           ViceLog(0, ("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                       afs_printable_VolumeId_lu(volptr->hashid)));
            return EIO;
        }
        if (CheckLength(volptr, targetptr, DataLength)) {
@@ -6445,8 +6506,8 @@ StoreData_RXStyle(Volume * volptr, Vnode * targetptr, struct AFSFid * Fid,
     }
     if (!VALID_INO(tinode)) {
        VTakeOffline(volptr);
-       ViceLog(0,("Volume %u now offline, must be salvaged.\n",
-                  volptr->hashid));
+       ViceLog(0,("Volume %" AFS_VOLID_FMT " now offline, must be salvaged.\n",
+                  afs_printable_VolumeId_lu(volptr->hashid)));
        return EIO;
     }
 
@@ -6500,6 +6561,7 @@ StoreData_RXStyle(Volume * volptr, Vnode * targetptr, struct AFSFid * Fid,
        /* Set the file's length; we've already done an lseek to the right
         * spot above.
         */
+       tlen = 0; /* Just a source of data for the write */
        nBytes = FDH_PWRITE(fdP, &tlen, 1, Pos);
        if (nBytes != 1) {
            errorCode = -1;
@@ -6760,18 +6822,20 @@ SRXAFS_CallBackRxConnAddr (struct rx_call * acall, afs_int32 *addr)
     static struct rx_securityClass *sc = 0;
     int i,j;
     struct rx_connection *conn;
+    afs_int32 viceid = -1;
 #endif
 
-    if ((errorCode = CallPreamble(acall, ACTIVECALL, &tcon, &tcallhost)))
+    if ((errorCode = CallPreamble(acall, ACTIVECALL, NULL, &tcon, &tcallhost)))
            goto Bad_CallBackRxConnAddr1;
 
 #ifndef __EXPERIMENTAL_CALLBACK_CONN_MOVING
     errorCode = 1;
 #else
     H_LOCK;
-    tclient = h_FindClient_r(tcon);
+    tclient = h_FindClient_r(tcon, &viceid);
     if (!tclient) {
        errorCode = VBUSY;
+       LogClientError("Client host too busy (CallBackRxConnAddr)", tcon, viceid, NULL);
        goto Bad_CallBackRxConnAddr;
     }
     thost = tclient->host;