From ab22c7a587126c100d3c4fe40465f5ba3ebc25f4 Mon Sep 17 00:00:00 2001 From: Jeffrey Altman Date: Sat, 23 Jul 2005 02:16:06 +0000 Subject: [PATCH] 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. --- src/WINNT/afsd/cm_conn.c | 12 ++++++++++- src/WINNT/afsd/cm_scache.c | 31 +++++++++++++++++++++----- src/WINNT/afsd/cm_vnodeops.c | 24 +++++++++++++++++++-- src/WINNT/afsd/smb3.c | 42 ++++++++++++++++++++++++++++++------ 4 files changed, 95 insertions(+), 14 deletions(-) diff --git a/src/WINNT/afsd/cm_conn.c b/src/WINNT/afsd/cm_conn.c index ff2fb08aa..9e130f0d7 100644 --- 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 7b099a62a..afe29e105 100644 --- 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 61ffcd2a3..7162e77a2 100644 --- 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 ca638c66c..389449b22 100644 --- 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); -- 2.39.5