viced: Improve client error log messages
authorAndrew Deason <adeason@sinenomine.net>
Fri, 18 Oct 2013 00:22:48 +0000 (20:22 -0400)
committerDerrick Brashear <shadow@your-file-system.com>
Wed, 23 Oct 2013 12:35:10 +0000 (05:35 -0700)
Commit 6c41b1f740e16b5b9adfe9026630595be6f0699e improved a few log
messages to include the client ip and port of the request triggering
that log message. Include the viceid and fid (if applicable), too, so
an administrator may more easily identify the cause.

This creates the function LogClientError, so we can use a common
function for logging very similar information. This also modifies
h_FindClient_r to give the viceid to the caller, even in the case of
error. In addition, this modifies CallPreamble to accept a fid and
modifies all callers to accomodate.

Change-Id: I326e17538265ea3251db27a05ede25c33e9a230d
Reviewed-on: http://gerrit.openafs.org/10347
Tested-by: BuildBot <buildbot@rampaginggeek.com>
Reviewed-by: Derrick Brashear <shadow@your-file-system.com>

src/viced/afsfileprocs.c
src/viced/host.c
src/viced/host.h

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;
index d8165d7..57357ff 100644 (file)
@@ -2377,9 +2377,12 @@ getPeerDetails(struct rx_connection *conn,
  *
  * The refCount on client->host is returned incremented.  h_ReleaseClient_r
  * does not decrement the refCount on client->host.
+ *
+ * *a_viceid is set to the user's ViceId, even if we don't return a client
+ * struct.
  */
 struct client *
-h_FindClient_r(struct rx_connection *tcon)
+h_FindClient_r(struct rx_connection *tcon, afs_int32 *a_viceid)
 {
     struct client *client;
     struct host *host = NULL;
@@ -2398,6 +2401,9 @@ h_FindClient_r(struct rx_connection *tcon)
        && !(client->host->hostFlags & HOSTDELETED)
        && !client->deleted) {
 
+       if (a_viceid) {
+           *a_viceid = client->ViceId;
+       }
        client->refCount++;
        h_Hold_r(client->host);
        if (client->prfail != 2) {
@@ -2422,6 +2428,10 @@ h_FindClient_r(struct rx_connection *tcon)
     if (code)
        fail = 1;
 
+    if (a_viceid) {
+       *a_viceid = viceid;
+    }
+
     if (!client) { /* loop */
        host = h_GetHost_r(tcon);       /* Returns with incremented refCount  */
 
index 27092bb..8233869 100644 (file)
@@ -207,7 +207,7 @@ extern struct host *h_LookupUuid_r(afsUUID * uuidp);
 extern void h_Enumerate(int (*proc) (struct host *, void *), void *param);
 extern void h_Enumerate_r(int (*proc) (struct host *, void *), struct host *enumstart, void *param);
 extern struct host *h_GetHost_r(struct rx_connection *tcon);
-extern struct client *h_FindClient_r(struct rx_connection *tcon);
+extern struct client *h_FindClient_r(struct rx_connection *tcon, afs_int32 *viceid);
 extern int h_ReleaseClient_r(struct client *client);
 extern void h_TossStuff_r(struct host *host);
 extern void h_EnumerateClients(VolumeId vid,