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.

diff --git a/src/WINNT/afsd/cm_buf.c b/src/WINNT/afsd/cm_buf.c
index 74453db..b4bfaaf 100644 (file)
--- 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 a2e8653..b29d845 100644 (file)
--- 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);