From 6620b9452bb3f270ebabc29a910918b1f17225f4 Mon Sep 17 00:00:00 2001 From: Jeffrey Altman Date: Sun, 28 Aug 2005 04:29:31 +0000 Subject: [PATCH] windows-scache-deadlock-fix-20050827 It was reported that Microsoft Word when editing files stored in AFS would cause OAFW to fail to respond. It was determined that a scp->mx lock was not being released in buf_WaitIO if the no one was waiting on the scp. This patch corrects the deadlock and fixes some debugging messages. --- src/WINNT/afsd/cm_buf.c | 20 ++++++++++---------- src/WINNT/afsd/cm_dcache.c | 22 +++++++++++----------- 2 files changed, 21 insertions(+), 21 deletions(-) diff --git a/src/WINNT/afsd/cm_buf.c b/src/WINNT/afsd/cm_buf.c index 74453db214..b4bfaaf926 100644 --- a/src/WINNT/afsd/cm_buf.c +++ b/src/WINNT/afsd/cm_buf.c @@ -435,7 +435,7 @@ void buf_Release(cm_buf_t *bp) } /* wait for reading or writing to clear; called with write-locked - * buffer, and returns with locked buffer. + * buffer and unlocked scp and returns with locked buffer. */ void buf_WaitIO(cm_scache_t * scp, cm_buf_t *bp) { @@ -455,15 +455,15 @@ void buf_WaitIO(cm_scache_t * scp, cm_buf_t *bp) if ( bp->flags & CM_BUF_WAITING ) { bp->waitCount++; bp->waitRequests++; - osi_Log1(buf_logp, "buf_WaitIO CM_BUF_WAITING already set for 0x%x", bp); + osi_Log1(afsd_logp, "buf_WaitIO CM_BUF_WAITING already set for 0x%x", bp); } else { - osi_Log1(buf_logp, "buf_WaitIO CM_BUF_WAITING set for 0x%x", bp); + osi_Log1(afsd_logp, "buf_WaitIO CM_BUF_WAITING set for 0x%x", bp); bp->flags |= CM_BUF_WAITING; bp->waitCount = bp->waitRequests = 1; } osi_SleepM((long) bp, &bp->mx); lock_ObtainMutex(&bp->mx); - osi_Log1(buf_logp, "buf_WaitIO conflict wait done for 0x%x", bp); + osi_Log1(afsd_logp, "buf_WaitIO conflict wait done for 0x%x", bp); bp->waitCount--; if (bp->waitCount == 0) { osi_Log1(afsd_logp, "buf_WaitIO CM_BUF_WAITING reset for 0x%x", bp); @@ -477,10 +477,10 @@ void buf_WaitIO(cm_scache_t * scp, cm_buf_t *bp) if ( scp ) { lock_ObtainMutex(&scp->mx); if (scp->flags & CM_SCACHEFLAG_WAITING) { - osi_Log1(buf_logp, "buf_WaitIO waking scp 0x%x", scp); + osi_Log1(afsd_logp, "buf_WaitIO waking scp 0x%x", scp); osi_Wakeup((long)&scp->flags); - lock_ReleaseMutex(&scp->mx); } + lock_ReleaseMutex(&scp->mx); } } @@ -488,10 +488,10 @@ void buf_WaitIO(cm_scache_t * scp, cm_buf_t *bp) * the I/O to complete. Do so. */ if (bp->flags & CM_BUF_WAITING) { - osi_Log1(buf_logp, "buf_WaitIO Waking bp 0x%x", bp); + osi_Log1(afsd_logp, "buf_WaitIO Waking bp 0x%x", bp); osi_Wakeup((long) bp); } - osi_Log1(buf_logp, "WaitIO finished wait for bp 0x%x", (long) bp); + osi_Log1(afsd_logp, "WaitIO finished wait for bp 0x%x", (long) bp); } /* code to drop reference count while holding buf_globalLock */ @@ -563,11 +563,11 @@ void buf_LockedCleanAsync(cm_buf_t *bp, cm_req_t *reqp) while ((bp->flags & CM_BUF_DIRTY) == CM_BUF_DIRTY) { lock_ReleaseMutex(&bp->mx); - osi_Log1(buf_logp, "buf_LockedCleanAsync starts I/O on 0x%x", bp); + osi_Log1(afsd_logp, "buf_LockedCleanAsync starts I/O on 0x%x", bp); code = (*cm_buf_opsp->Writep)(&bp->fid, &bp->offset, cm_data.buf_blockSize, 0, bp->userp, reqp); - osi_Log2(buf_logp, "buf_LockedCleanAsync I/O on 0x%x, done=%d", bp, code); + osi_Log2(afsd_logp, "buf_LockedCleanAsync I/O on 0x%x, done=%d", bp, code); lock_ObtainMutex(&bp->mx); if (code) diff --git a/src/WINNT/afsd/cm_dcache.c b/src/WINNT/afsd/cm_dcache.c index a2e86533df..b29d845ea4 100644 --- a/src/WINNT/afsd/cm_dcache.c +++ b/src/WINNT/afsd/cm_dcache.c @@ -134,8 +134,8 @@ long cm_BufWrite(void *vfidp, osi_hyper_t *offsetp, long length, long flags, callp = rx_NewCall(rxconnp); rx_PutConnection(rxconnp); - osi_Log3(afsd_logp, "CALL StoreData scp 0x%x, off 0x%x, size 0x%x", - (long) scp, biod.offset.LowPart, nbytes); + osi_Log4(afsd_logp, "CALL StoreData scp 0x%x, offset 0x%x:%08x, length 0x%x", + (long) scp, biod.offset.HighPart, biod.offset.LowPart, nbytes); code = StartRXAFS_StoreData(callp, &tfid, &inStatus, biod.offset.LowPart, nbytes, truncPos); @@ -158,22 +158,22 @@ long cm_BufWrite(void *vfidp, osi_hyper_t *offsetp, long length, long flags, /* write out wbytes of data from bufferp */ temp = rx_Write(callp, bufferp, wbytes); if (temp != wbytes) { - osi_Log2(afsd_logp, "rx_Write failed %d != %d",temp,wbytes); + osi_Log3(afsd_logp, "rx_Write failed bp 0x%x, %d != %d",bufp,temp,wbytes); code = -1; break; } else { - osi_Log1(afsd_logp, "rx_Write succeeded %d",temp); + osi_Log2(afsd_logp, "rx_Write succeeded bp 0x%x, %d",bufp,temp); } nbytes -= wbytes; } /* while more bytes to write */ } /* if RPC started successfully */ else { - osi_Log1(afsd_logp, "StartRXAFS_StoreData failed (%lX)",code); + osi_Log2(afsd_logp, "StartRXAFS_StoreData scp 0x%x failed (%lX)",scp,code); } if (code == 0) { code = EndRXAFS_StoreData(callp, &outStatus, &volSync); if (code) - osi_Log1(afsd_logp, "EndRXAFS_StoreData failed (%lX)",code); + osi_Log2(afsd_logp, "EndRXAFS_StoreData scp 0x%x failed (%lX)",scp,code); } code = rx_EndCall(callp, code); @@ -181,9 +181,9 @@ long cm_BufWrite(void *vfidp, osi_hyper_t *offsetp, long length, long flags, code = cm_MapRPCError(code, reqp); if (code) - osi_Log1(afsd_logp, "CALL StoreData FAILURE, code 0x%x", code); + osi_Log2(afsd_logp, "CALL StoreData FAILURE scp 0x%x, code 0x%x", scp, code); else - osi_Log0(afsd_logp, "CALL StoreData SUCCESS"); + osi_Log1(afsd_logp, "CALL StoreData SUCCESS scp 0x%x", scp); /* now, clean up our state */ lock_ObtainMutex(&scp->mx); @@ -492,7 +492,7 @@ void cm_BkgStore(cm_scache_t *scp, long p1, long p2, long p3, long p4, toffset.HighPart = p2; length = p3; - osi_Log2(afsd_logp, "Starting BKG store vp 0x%x, base 0x%x", scp, p1); + osi_Log4(afsd_logp, "Starting BKG store scp 0x%x, offset 0x%x:%08x, length 0x%x", scp, p2, p1, p3); cm_BufWrite(&scp->fid, &toffset, length, /* flags */ 0, userp, &req); @@ -536,7 +536,7 @@ void cm_BkgPrefetch(cm_scache_t *scp, long p1, long p2, long p3, long p4, base.HighPart = p2; length = p3; - osi_Log2(afsd_logp, "Starting BKG prefetch vp 0x%x, base 0x%x", scp, p1); + osi_Log2(afsd_logp, "Starting BKG prefetch scp 0x%x, base 0x%x", scp, p1); code = buf_Get(scp, &base, &bp); @@ -1093,7 +1093,7 @@ void cm_ReleaseBIOD(cm_bulkIO_t *biop, int isStore) /* turn off writing and wakeup users */ if (isStore) { if (bufp->flags & CM_BUF_WAITING) { - osi_Log1(afsd_logp, "cm_ReleaseBIOD Waking bp 0x%x", bufp); + osi_Log2(afsd_logp, "cm_ReleaseBIOD Waking [scp 0x%x] bp 0x%x", scp, bufp); osi_Wakeup((long) bufp); } bufp->flags &= ~(CM_BUF_WRITING | CM_BUF_DIRTY);