windows-misc-20050722

Add debug logging to SMB and CM Locking code

Optimize cm_Analyze by only performing a cm_CheckServers on the current
cell instead of all cells

Add code to detect loops to the cm_scache_t validation routines.

diff --git a/src/WINNT/afsd/cm_conn.c b/src/WINNT/afsd/cm_conn.c
index ff2fb08..9e130f0 100644 (file)
--- a/src/WINNT/afsd/cm_conn.c
+++ b/src/WINNT/afsd/cm_conn.c
@@ -146,6 +146,7 @@ cm_Analyze(cm_conn_t *connp, cm_user_t *userp, cm_req_t *reqp,
     cm_server_t *serverp = NULL;
     cm_serverRef_t **serverspp = NULL;
     cm_serverRef_t *tsrp;
+    cm_cell_t  *cellp = NULL;
     cm_ucell_t *ucellp;
     int retry = 0;
     int free_svr_list = 0;
@@ -200,7 +201,16 @@ cm_Analyze(cm_conn_t *connp, cm_user_t *userp, cm_req_t *reqp,
     if (errorCode == CM_ERROR_TIMEDOUT) {
         if (timeLeft > 5 ) {
             thrd_Sleep(3000);
-            cm_CheckServers(CM_FLAG_CHECKDOWNSERVERS, NULL);
+            if (cellp == NULL && serverp)
+                cellp = serverp->cellp;
+            if (cellp == NULL && serversp) {
+                struct cm_serverRef * refp;
+                for ( refp=serversp ; cellp == NULL && refp != NULL; refp=refp->next) {
+                    if ( refp->server )
+                        cellp = refp->server->cellp;
+                }
+            }
+            cm_CheckServers(CM_FLAG_CHECKDOWNSERVERS, cellp);
             retry = 1;
         }
     } 

diff --git a/src/WINNT/afsd/cm_scache.c b/src/WINNT/afsd/cm_scache.c
index 7b099a6..afe29e1 100644 (file)
--- a/src/WINNT/afsd/cm_scache.c
+++ b/src/WINNT/afsd/cm_scache.c
@@ -200,11 +200,12 @@ void cm_fakeSCacheInit(int newFile)
 long
 cm_ValidateSCache(void)
 {
-    cm_scache_t * scp;
+    cm_scache_t * scp, *lscp;
     long i;
 
-    for ( scp = cm_data.scacheLRUFirstp; scp;
-          scp = (cm_scache_t *) osi_QNext(&scp->q) ) {
+    for ( scp = cm_data.scacheLRUFirstp, lscp = NULL, i = 0; 
+          scp;
+          lscp = scp, scp = (cm_scache_t *) osi_QNext(&scp->q), i++ ) {
         if (scp->magic != CM_SCACHE_MAGIC) {
             afsi_log("cm_ValidateSCache failure: scp->magic != CM_SCACHE_MAGIC");
             fprintf(stderr, "cm_ValidateSCache failure: scp->magic != CM_SCACHE_MAGIC\n");
@@ -225,10 +226,20 @@ cm_ValidateSCache(void)
             fprintf(stderr, "cm_ValidateSCache failure: scp->volp->magic != CM_VOLUME_MAGIC\n");
             return -4;
         }
+        if (i > cm_data.currentSCaches ) {
+            afsi_log("cm_ValidateSCache failure: LRU First queue loops");
+            fprintf(stderr, "cm_ValidateSCache failure: LUR First queue loops\n");
+            return -13;
+        }
+        if (lscp != (cm_scache_t *) osi_QPrev(&scp->q)) {
+            afsi_log("cm_ValidateSCache failure: QPrev(scp) != previous");
+            fprintf(stderr, "cm_ValidateSCache failure: QPrev(scp) != previous\n");
+            return -15;
+        }
     }
 
-    for ( scp = cm_data.scacheLRULastp; scp;
-          scp = (cm_scache_t *) osi_QPrev(&scp->q) ) {
+    for ( scp = cm_data.scacheLRULastp, lscp = NULL, i = 0; scp;
+          lscp = scp, scp = (cm_scache_t *) osi_QPrev(&scp->q), i++ ) {
         if (scp->magic != CM_SCACHE_MAGIC) {
             afsi_log("cm_ValidateSCache failure: scp->magic != CM_SCACHE_MAGIC");
             fprintf(stderr, "cm_ValidateSCache failure: scp->magic != CM_SCACHE_MAGIC\n");
@@ -249,6 +260,16 @@ cm_ValidateSCache(void)
             fprintf(stderr, "cm_ValidateSCache failure: scp->volp->magic != CM_VOLUME_MAGIC\n");
             return -8;
         }
+        if (i > cm_data.currentSCaches ) {
+            afsi_log("cm_ValidateSCache failure: LRU Last queue loops");
+            fprintf(stderr, "cm_ValidateSCache failure: LUR Last queue loops\n");
+            return -14;
+        }
+        if (lscp != (cm_scache_t *) osi_QNext(&scp->q)) {
+            afsi_log("cm_ValidateSCache failure: QNext(scp) != next");
+            fprintf(stderr, "cm_ValidateSCache failure: QNext(scp) != next\n");
+            return -16;
+        }
     }
 
     for ( i=0; i < cm_data.hashTableSize; i++ ) {

diff --git a/src/WINNT/afsd/cm_vnodeops.c b/src/WINNT/afsd/cm_vnodeops.c
index 61ffcd2..7162e77 100644 (file)
--- a/src/WINNT/afsd/cm_vnodeops.c
+++ b/src/WINNT/afsd/cm_vnodeops.c
@@ -2706,6 +2706,10 @@ long cm_Lock(cm_scache_t *scp, unsigned char LockType,
     int found = 0;
     struct rx_connection * callp;
 
+    osi_Log1(afsd_logp, "cm_Lock scp 0x%x ...", (long) scp);
+    osi_Log4(afsd_logp, "cm_Lock type 0x%x offset %d length %d timeout %d",
+             LockType, (unsigned long)LOffset.QuadPart, (unsigned long)LLength.QuadPart, Timeout);
+
     /* Look for a conflict.  Also, if we are asking for a shared lock,
      * look for another shared lock, so we don't have to do an RPC.
      */
@@ -2721,6 +2725,8 @@ long cm_Lock(cm_scache_t *scp, unsigned char LockType,
         q = osi_QNext(q);
     }
 
+    osi_Log1(afsd_logp, "cm_Lock found = %d", found);
+
     if (found)
         code = 0;
     else {
@@ -2729,6 +2735,7 @@ long cm_Lock(cm_scache_t *scp, unsigned char LockType,
         tfid.Unique = scp->fid.unique;
         lock_ReleaseMutex(&scp->mx);
         do {
+            osi_Log1(afsd_logp, "CALL SetLock scp 0x%x", (long) scp);
             code = cm_Conn(&scp->fid, userp, reqp, &connp);
             if (code) 
                 break;
@@ -2740,6 +2747,10 @@ long cm_Lock(cm_scache_t *scp, unsigned char LockType,
 
         } while (cm_Analyze(connp, userp, reqp, &scp->fid, &volSync,
                              NULL, NULL, code));
+        if (code)
+            osi_Log1(afsd_logp, "CALL SetLock FAILURE, code 0x%x", code);
+        else
+            osi_Log0(afsd_logp, "CALL SetLock SUCCESS");
         lock_ObtainMutex(&scp->mx);
         code = cm_MapRPCError(code, reqp);
     }
@@ -2759,6 +2770,7 @@ long cm_Lock(cm_scache_t *scp, unsigned char LockType,
         lock_ReleaseWrite(&cm_scacheLock);
         if (code != 0) 
             *lockpp = fileLock;
+        osi_Log1(afsd_logp, "cm_Lock Lock added 0x%x", (long) fileLock);
     }
     return code;
 }
@@ -2779,6 +2791,9 @@ long cm_Unlock(cm_scache_t *scp, unsigned char LockType,
     int found = 0;
     struct rx_connection * callp;
 
+    osi_Log4(afsd_logp, "cm_Unlock scp 0x%x type 0x%x offset %d length %d",
+             (long) scp, LockType, (unsigned long)LOffset.QuadPart, (unsigned long)LLength.QuadPart);
+
     if (LargeIntegerLessThan(LLength, scp->length))
         smallLock = 1;
 
@@ -2803,12 +2818,16 @@ long cm_Unlock(cm_scache_t *scp, unsigned char LockType,
     }
 
     /* ignore byte ranges */
-    if (smallLock && !found)
+    if (smallLock && !found) {
+        osi_Log0(afsd_logp, "cm_Unlock lock not found and ignored");
         return 0;
+    }
 
     /* don't try to unlock other people's locks */
-    if (!found)
+    if (!found) {
+        osi_Log0(afsd_logp, "cm_Unlock lock not found; failure");
         return CM_ERROR_WOULDBLOCK;
+    }
 
     /* discard lock record */
     osi_QRemove(&scp->fileLocks, qq);
@@ -2848,6 +2867,7 @@ long cm_Unlock(cm_scache_t *scp, unsigned char LockType,
         lock_ObtainMutex(&scp->mx);
     }
 
+    osi_Log1(afsd_logp, "cm_Unlock code 0x%x", code);
     return code;
 }
 

diff --git a/src/WINNT/afsd/smb3.c b/src/WINNT/afsd/smb3.c
index ca638c6..389449b 100644 (file)
--- a/src/WINNT/afsd/smb3.c
+++ b/src/WINNT/afsd/smb3.c
@@ -4783,6 +4783,15 @@ long smb_ReceiveV3OpenX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
     return 0;
 }       
 
+/* The file locking code is incomplete and that which is implemented in cm_Lock()
+ * is broken.  What exists functions only because it is rarely if ever called.
+ * The tests activated by FULL_LOCKS_ONLY ensure that cm_Lock() is only called
+ * if the lock covers the entire file.  Therefore, RXAFS_SetLock is only called 
+ * rarely.   That means that AFS locks are ignored by Windows clients.
+ * When cm_Lock is re-written, undefine or better yet remove, the FULL_LOCKS_ONLY
+ * code.
+ */
+#define FULL_LOCKS_ONLY
 long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
 {
     cm_req_t req;
@@ -4807,6 +4816,7 @@ long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
 
     fidp = smb_FindFID(vcp, fid, 0);
     if (!fidp || (fidp->flags & SMB_FID_IOCTL)) {
+        osi_Log0(smb_logp, "smb_ReceiveV3Locking BadFD");
         return CM_ERROR_BADFD;
     }
     /* set inp->fid so that later read calls in same msg can find fid */
@@ -4821,8 +4831,10 @@ long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
                       CM_SCACHESYNC_NEEDCALLBACK
                         | CM_SCACHESYNC_GETSTATUS
                         | CM_SCACHESYNC_LOCK);
-    if (code) 
+    if (code) {
+        osi_Log1(smb_logp, "smb_ReceiveV3Locking SyncOp failure code 0x%x", code);
         goto doneSync;
+    }
 
     LockType = smb_GetSMBParm(inp, 3) & 0xff;
     Timeout = (smb_GetSMBParm(inp, 5) << 16) + smb_GetSMBParm(inp, 4);
@@ -4848,8 +4860,13 @@ long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
             LLength.LowPart = *((DWORD *)(op + 6));
             op += 10;
         }
-        if (LargeIntegerNotEqualToZero(LOffset))
+#ifdef FULL_LOCKS_ONLY
+        if (LargeIntegerNotEqualToZero(LOffset)) {
+            osi_Log2(smb_logp, "smb_ReceiveV3Locking Unlock %d offset 0x%x != Zero",
+                     i, (long)LOffset.QuadPart);
             continue;
+        }
+#endif /* FULL_LOCKS_ONLY */
         /* Do not check length -- length check done in cm_Unlock */
 
         code = cm_Unlock(scp, LockType, LOffset, LLength, userp, &req);
@@ -4873,11 +4890,18 @@ long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
             LLength.LowPart = *((DWORD *)(op + 6));
             op += 10;
         }
-        if (LargeIntegerNotEqualToZero(LOffset))
+#ifdef FULL_LOCKS_ONLY
+        if (LargeIntegerNotEqualToZero(LOffset)) {
+            osi_Log2(smb_logp, "smb_ReceiveV3Locking Lock %d offset 0x%x != Zero",
+                     i, (long)LOffset.QuadPart);
             continue;
-        if (LargeIntegerLessThan(LOffset, scp->length))
+        }
+        if (LargeIntegerLessThan(LOffset, scp->length)) {
+            osi_Log3(smb_logp, "smb_ReceiveV3Locking Unlock %d offset 0x%x < 0x%x",
+                     i, (long)LOffset.QuadPart, (long)scp->length.QuadPart);
             continue;
-
+        }
+#endif /* FULL_LOCKS_ONLY */
         code = cm_Lock(scp, LockType, LOffset, LLength, Timeout,
                         userp, &req, &lockp);
         if (code == CM_ERROR_WOULDBLOCK && Timeout != 0) {
@@ -4896,13 +4920,19 @@ long smb_ReceiveV3LockingX(smb_vc_t *vcp, smb_packet_t *inp, smb_packet_t *outp)
             lock_ReleaseWrite(&smb_globalLock);
             /* don't send reply immediately */
             outp->flags |= SMB_PACKETFLAG_NOSEND;
+            osi_Log1(smb_logp, "smb_ReceiveV3Locking WaitingLock created 0x%x",
+                     (long) waitingLock);
+            continue;
         }
-        if (code) 
+        if (code) {
+            osi_Log1(smb_logp, "smb_ReceiveV3Locking cm_Lock failure code 0x%x", code);
             break;
+        }
     }           
 
     if (code) {
         /* release any locks acquired before the failure */
+        osi_Log0(smb_logp, "smb_ReceiveV3Locking - failure; should be releasing locks but don't!!!!");
     }
     else
         smb_SetSMBDataLength(outp, 0);