viced: Improve client error log messages
[openafs.git] / src / viced / afsfileprocs.c
index 62652b3..f178a96 100644 (file)
@@ -316,17 +316,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,13 +368,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 struct for host "
-                   "%s:%d, sending busy signal\n",
-                   afs_inet_ntoa_r(rx_HostOf(rx_PeerOf(*tconn)), hoststr),
-                   (int)ntohs(rx_PortOf(rx_PeerOf(*tconn)))));
        H_UNLOCK;
+       LogClientError("Client host too busy", *tconn, viceid, Fid);
        return VBUSY;
     }
     thost = tclient->host;
@@ -355,11 +379,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 for client from host "
-                       "%s:%d, failing request\n",
-                       afs_inet_ntoa_r(thost->host, hoststr),
-                       (int)ntohs(thost->port)));
            H_UNLOCK;
+           LogClientError("Cannot get CPS for client", *tconn, viceid, Fid);
            return -1001;
        }
        retry_flag = 0;         /* Retry once */
@@ -386,10 +407,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 while "
-                       "handling request for %s:%d\n",
-                       afs_inet_ntoa_r(thost->host, hoststr),
-                       (int)ntohs(thost->port)));
+           LogClientError("Cannot reconnect to ptserver", *tconn, viceid, Fid);
            return -1001;
        }
 
@@ -458,7 +476,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;
@@ -2262,7 +2280,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 */
@@ -2414,7 +2432,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 */
@@ -2598,10 +2616,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
@@ -2723,11 +2742,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
@@ -2846,7 +2866,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);
@@ -2898,7 +2918,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 */
@@ -3046,7 +3066,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 */
@@ -3218,7 +3238,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);
@@ -3350,7 +3370,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);
@@ -3488,7 +3508,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 =
@@ -3992,7 +4012,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 =
@@ -4172,7 +4192,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 =
@@ -4349,7 +4369,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 =
@@ -4519,7 +4539,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 =
@@ -4649,7 +4669,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);
@@ -4753,7 +4773,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);
@@ -4851,7 +4871,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);
@@ -4960,7 +4980,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);
@@ -5064,7 +5084,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"));
@@ -5102,7 +5122,7 @@ 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"));
@@ -5541,7 +5561,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) {
@@ -5640,7 +5660,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);
@@ -5858,7 +5878,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;
@@ -5901,7 +5921,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;
@@ -5973,7 +5993,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;
@@ -6040,7 +6060,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++;
@@ -6091,7 +6111,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;
@@ -6117,7 +6137,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;
@@ -6810,18 +6830,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;