callback-deadlock-20040819
[openafs.git] / src / WINNT / afsd / cm_callback.c
index 507d9f5..950a2db 100644 (file)
 
 #include "afsd.h"
 
+/*extern void afsi_log(char *pattern, ...);*/
+
 /* read/write lock for all global storage in this module */
 osi_rwlock_t cm_callbackLock;
 
-/*
-#ifdef AFS_FREELANCE_CLIENT
-extern int cm_fakeDirCallback;
-extern int cm_fakeGettingCallback;
-#endif
-*/
 #ifdef AFS_FREELANCE_CLIENT
 extern osi_mutex_t cm_Freelance_Lock;
 #endif
@@ -77,6 +73,10 @@ void cm_RecordRacingRevoke(cm_fid_t *fidp, long cancelFlags)
        cm_racingRevokes_t *rp;
 
        lock_ObtainWrite(&cm_callbackLock);
+
+    osi_Log3(afsd_logp, "RecordRacingRevoke Volume %d Flags %lX activeCalls %d",
+             fidp->volume, cancelFlags, cm_activeCallbackGrantingCalls);
+
        if (cm_activeCallbackGrantingCalls > 0) {
                rp = malloc(sizeof(*rp));
                memset(rp, 0, sizeof(*rp));
@@ -90,30 +90,34 @@ void cm_RecordRacingRevoke(cm_fid_t *fidp, long cancelFlags)
 
 /*
  * When we lose a callback, may have to send change notification replies.
+ * Do not call with a lock on the scp.
  */
 void cm_CallbackNotifyChange(cm_scache_t *scp)
 {
-       if (scp->fileType == CM_SCACHETYPE_DIRECTORY) {
-               if (scp->flags & CM_SCACHEFLAG_ANYWATCH)
-                       smb_NotifyChange(0,
-                        FILE_NOTIFY_GENERIC_DIRECTORY_FILTER,
-                        scp, NULL, NULL, TRUE);
-       } else {
-               cm_fid_t tfid;
-               cm_scache_t *dscp;
-
-               tfid.cell = scp->fid.cell;
-               tfid.volume = scp->fid.volume;
-               tfid.vnode = scp->parentVnode;
-               tfid.unique = scp->parentUnique;
-               dscp = cm_FindSCache(&tfid);
-               if (dscp &&
-                       dscp->flags & CM_SCACHEFLAG_ANYWATCH)
-                       smb_NotifyChange(0,
-                        FILE_NOTIFY_GENERIC_FILE_FILTER,
-                        dscp, NULL, NULL, TRUE);
-               if (dscp) cm_ReleaseSCache(dscp);
-       }
+    osi_Log2(afsd_logp, "CallbackNotifyChange FileType %d Flags %lX",
+              scp->fileType, scp->flags);
+
+    if (scp->fileType == CM_SCACHETYPE_DIRECTORY) {
+        if (scp->flags & CM_SCACHEFLAG_ANYWATCH)
+            smb_NotifyChange(0,
+                             FILE_NOTIFY_GENERIC_DIRECTORY_FILTER,
+                             scp, NULL, NULL, TRUE);
+    } else {
+        cm_fid_t tfid;
+        cm_scache_t *dscp;
+
+        tfid.cell = scp->fid.cell;
+        tfid.volume = scp->fid.volume;
+        tfid.vnode = scp->parentVnode;
+        tfid.unique = scp->parentUnique;
+        dscp = cm_FindSCache(&tfid);
+        if (dscp &&
+             dscp->flags & CM_SCACHEFLAG_ANYWATCH)
+            smb_NotifyChange( 0,
+                              FILE_NOTIFY_GENERIC_FILE_FILTER,
+                              dscp,   NULL, NULL, TRUE);
+        if (dscp) cm_ReleaseSCache(dscp);
+    }
 }
 
 /* called with no locks held for every file ID that is revoked directly by
@@ -138,7 +142,7 @@ void cm_RevokeCallback(struct rx_call *callp, AFSFid *fidp)
         tfid.unique = fidp->Unique;
         hash = CM_SCACHE_HASH(&tfid);
 
-       osi_Log3(afsd_logp, "Revoke callback vol %d vn %d un %d",
+    osi_Log3(afsd_logp, "RevokeCallback vol %d vn %d un %d",
                 fidp->Volume, fidp->Vnode, fidp->Unique);
         
        /* do this first, so that if we're executing a callback granting call
@@ -158,7 +162,7 @@ void cm_RevokeCallback(struct rx_call *callp, AFSFid *fidp)
                         scp->fid.unique == tfid.unique) {
                        scp->refCount++;
                        lock_ReleaseWrite(&cm_scacheLock);
-                       osi_Log1(afsd_logp, "Revoke scp %x", scp);
+            osi_Log1(afsd_logp, "Discarding SCache scp %x", scp);
                         lock_ObtainMutex(&scp->mx);
                        cm_DiscardSCache(scp);
                         lock_ReleaseMutex(&scp->mx);
@@ -181,6 +185,8 @@ void cm_RevokeVolumeCallback(struct rx_call *callp, AFSFid *fidp)
         cm_scache_t *scp;
         cm_fid_t tfid;
 
+    osi_Log1(afsd_logp, "RevokeVolumeCallback %d", fidp->Volume);
+
        /* do this first, so that if we're executing a callback granting call
          * at this moment, we kill it before it can be merged in.  Otherwise,
          * it could complete while we're doing the scan below, and get missed
@@ -190,7 +196,6 @@ void cm_RevokeVolumeCallback(struct rx_call *callp, AFSFid *fidp)
         tfid.volume = fidp->Volume;
         cm_RecordRacingRevoke(&tfid, CM_RACINGFLAG_CANCELVOL);
 
-       osi_Log1(afsd_logp, "Revoke Volume %d", fidp->Volume);
 
         lock_ObtainWrite(&cm_scacheLock);
        for(hash = 0; hash < cm_hashTableSize; hash++) {
@@ -199,6 +204,7 @@ void cm_RevokeVolumeCallback(struct rx_call *callp, AFSFid *fidp)
                                scp->refCount++;
                                lock_ReleaseWrite(&cm_scacheLock);
                                lock_ObtainMutex(&scp->mx);
+                osi_Log1(afsd_logp, "Discarding SCache scp %x", scp);
                                cm_DiscardSCache(scp);
                                lock_ReleaseMutex(&scp->mx);
                                cm_CallbackNotifyChange(scp);
@@ -219,13 +225,17 @@ SRXAFSCB_CallBack(struct rx_call *callp, AFSCBFids *fidsArrayp, AFSCBs *cbsArray
         int i;
         AFSFid *tfidp;
         
+    osi_Log0(afsd_logp, "SRXAFSCB_CallBack");
+
         for(i=0; i < (long) fidsArrayp->AFSCBFids_len; i++) {
                tfidp = &fidsArrayp->AFSCBFids_val[i];
                 
-                if (tfidp->Volume == 0) continue;      /* means don't do anything */
+        if (tfidp->Volume == 0)
+            continue;   /* means don't do anything */
                 else if (tfidp->Vnode == 0)
                        cm_RevokeVolumeCallback(callp, tfidp);
-               else cm_RevokeCallback(callp, tfidp);
+        else
+            cm_RevokeCallback(callp, tfidp);
         }
 
        return 0;
@@ -243,6 +253,8 @@ SRXAFSCB_InitCallBackState(struct rx_call *callp)
     int hash;
     int discarded;
 
+    osi_Log0(afsd_logp, "SRXAFSCB_InitCallBackState");
+
     if ((rx_ConnectionOf(callp)) && (rx_PeerOf(rx_ConnectionOf(callp)))) {
        taddr.sin_family = AF_INET;
        taddr.sin_addr.s_addr = rx_HostOf(rx_PeerOf(rx_ConnectionOf(callp)));
@@ -285,6 +297,7 @@ SRXAFSCB_InitCallBackState(struct rx_call *callp)
                        if (scp->cbServerp != NULL) {
                                /* we have a callback, now decide if we should clear it */
                                if (scp->cbServerp == tsp || tsp == NULL) {
+                        osi_Log1(afsd_logp, "Discarding SCache scp %x", scp);
                                        cm_DiscardSCache(scp);
                                        discarded = 1;
                                }
@@ -309,6 +322,7 @@ SRXAFSCB_InitCallBackState(struct rx_call *callp)
 /* just returns if we're up */
 SRXAFSCB_Probe(struct rx_call *callp)
 {
+    osi_Log0(afsd_logp, "SRXAFSCB_Probe - not implemented");
        return 0;
 }
 
@@ -316,6 +330,7 @@ SRXAFSCB_Probe(struct rx_call *callp)
 SRXAFSCB_GetCE64(struct rx_call *callp, long index, AFSDBCacheEntry *cep)
 {
     /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_GetCE64 - not implemented");
     return RXGEN_OPCODE;
 }
 
@@ -323,6 +338,7 @@ SRXAFSCB_GetCE64(struct rx_call *callp, long index, AFSDBCacheEntry *cep)
 SRXAFSCB_GetLock(struct rx_call *callp, long index, AFSDBLock *lockp)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_GetLock - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -330,6 +346,7 @@ SRXAFSCB_GetLock(struct rx_call *callp, long index, AFSDBLock *lockp)
 SRXAFSCB_GetCE(struct rx_call *callp, long index, AFSDBCacheEntry *cep)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_GetCE - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -337,6 +354,7 @@ SRXAFSCB_GetCE(struct rx_call *callp, long index, AFSDBCacheEntry *cep)
 SRXAFSCB_XStatsVersion(struct rx_call *callp, long *vp)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_XStatsVersion - not implemented");
        *vp = -1;
        return RXGEN_OPCODE;
 }
@@ -346,6 +364,7 @@ SRXAFSCB_GetXStats(struct rx_call *callp, long cvn, long coln, long *srvp, long
        AFSCB_CollData *datap)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_GetXStats - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -353,6 +372,7 @@ SRXAFSCB_GetXStats(struct rx_call *callp, long cvn, long coln, long *srvp, long
 SRXAFSCB_InitCallBackState2(struct rx_call *callp, struct interfaceAddr* addr)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_InitCallBackState2 - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -360,6 +380,7 @@ SRXAFSCB_InitCallBackState2(struct rx_call *callp, struct interfaceAddr* addr)
 SRXAFSCB_WhoAreYou(struct rx_call *callp, struct interfaceAddr* addr)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_WhoAreYou - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -367,6 +388,7 @@ SRXAFSCB_WhoAreYou(struct rx_call *callp, struct interfaceAddr* addr)
 SRXAFSCB_InitCallBackState3(struct rx_call *callp, afsUUID* serverUuid)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_InitCallBackState3 - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -374,6 +396,7 @@ SRXAFSCB_InitCallBackState3(struct rx_call *callp, afsUUID* serverUuid)
 SRXAFSCB_ProbeUuid(struct rx_call *callp, afsUUID* clientUuid)
 {
        /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_ProbeUuid - not implemented");
        return RXGEN_OPCODE;
 }
 
@@ -405,6 +428,8 @@ int SRXAFSCB_GetServerPrefs(
     afs_int32 *a_srvr_addr,
     afs_int32 *a_srvr_rank)
 {
+    osi_Log0(afsd_logp, "SRXAFSCB_GetServerPrefs - not implemented");
+
     *a_srvr_addr = 0xffffffff;
     *a_srvr_rank = 0xffffffff;
     return 0;
@@ -440,6 +465,8 @@ int SRXAFSCB_GetCellServDB(
 {
     char *t_name;
 
+    osi_Log0(afsd_logp, "SRXAFSCB_GetCellServDB - not implemented");
+
     t_name = (char *)malloc(AFSNAMEMAX);
     t_name[0] = '\0';
     *a_name = t_name;
@@ -473,6 +500,8 @@ int SRXAFSCB_GetLocalCell(
 {
     char *t_name;
 
+    osi_Log0(afsd_logp, "SRXAFSCB_GetLocalCell");
+
     if (cm_rootCellp) {
        t_name = (char *)malloc(strlen(cm_rootCellp->namep)+1);
         strcpy(t_name, cm_rootCellp->namep);
@@ -558,6 +587,8 @@ cacheConfig *config;
     size_t allocsize;
     extern cm_initparams_v1 cm_initParams;
 
+    osi_Log0(afsd_logp, "SRXAFSCB_GetCacheConfig - version 1 only");
+
     /*
      * Currently only support version 1
      */
@@ -604,10 +635,14 @@ int cm_HaveCallback(cm_scache_t *scp)
     // good shape and we simply return true, provided no change is detected.
   int fdc, fgc;
 
-    if (cm_freelanceEnabled && scp->fid.cell==0x1 && scp->fid.volume==0x20000001) {    // if it's something on /afs
-       if (!(scp->fid.vnode==0x1 && scp->fid.unique==0x1))     // if it's not root.afs
+    if (cm_freelanceEnabled && 
+         scp->fid.cell==AFS_FAKE_ROOT_CELL_ID && scp->fid.volume==AFS_FAKE_ROOT_VOL_ID) {
+        /* if it's something on /afs */
+        if (!(scp->fid.vnode==0x1 && scp->fid.unique==0x1)) {
+            /* if it's not root.afs */
            return 1;
-       else {
+        }
+
            lock_ObtainMutex(&cm_Freelance_Lock);
            fdc = cm_fakeDirCallback;
            fgc = cm_fakeGettingCallback;
@@ -618,19 +653,21 @@ int cm_HaveCallback(cm_scache_t *scp)
            } else if (fdc==2 && !fgc) {        // we're in good shape
                if (cm_getLocalMountPointChange()) {    // check for changes
                    cm_clearLocalMountPointChange(); // clear the changefile
+            lock_ReleaseMutex(&scp->mx);      // this is re-locked in reInitLocalMountPoints
                    cm_reInitLocalMountPoints();        // start reinit
+            lock_ObtainMutex(&scp->mx);      // now get the lock back 
                    return 0;
                }
                return 1;                       // no change
            }
            return 0;
        }
-    }
 #endif
 
     if (scp->cbServerp != NULL)
        return 1;
-    else return 0;
+    else 
+        return 0;
 }
 
 /* need to detect a broken callback that races with our obtaining a callback.
@@ -674,6 +711,7 @@ void cm_EndCallbackGrantingCall(cm_scache_t *scp, cm_callbackRequest_t *cbrp,
        cm_racingRevokes_t *revp;               /* where we are */
        cm_racingRevokes_t *nrevp;              /* where we'll be next */
         int freeFlag;
+    cm_server_t * serverp = 0;
 
        lock_ObtainWrite(&cm_callbackLock);
        if (flags & CM_CALLBACK_MAINTAINCOUNT) {
@@ -682,13 +720,23 @@ void cm_EndCallbackGrantingCall(cm_scache_t *scp, cm_callbackRequest_t *cbrp,
        else {
                osi_assert(cm_activeCallbackGrantingCalls-- > 0);
        }
-        if (cm_activeCallbackGrantingCalls == 0) freeFlag = 1;
-        else freeFlag = 0;
+    if (cm_activeCallbackGrantingCalls == 0) 
+        freeFlag = 1;
+    else 
+        freeFlag = 0;
 
        /* record the callback; we'll clear it below if we really lose it */
+    if (cbrp) {
        if (scp) {
+            if (scp->cbServerp != cbrp->serverp) {
+                serverp = scp->cbServerp;
+            }
                scp->cbServerp = cbrp->serverp;
                scp->cbExpires = cbrp->startTime + cbp->ExpirationTime;
+        } else {
+            serverp = cbrp->serverp;
+        }
+        cbrp->serverp = NULL;
        }
 
        /* a callback was actually revoked during our granting call, so
@@ -703,10 +751,9 @@ void cm_EndCallbackGrantingCall(cm_scache_t *scp, cm_callbackRequest_t *cbrp,
                  * callback-granting call, and if this fid is the right fid,
                  * then clear the callback.
                  */
-                if (scp && cbrp->callbackCount != cm_callbackCount
+        if (scp && cbrp && cbrp->callbackCount != cm_callbackCount
                                && revp->callbackCount > cbrp->callbackCount
-                               && (
-                               (scp->fid.volume == revp->fid.volume &&
+             && (( scp->fid.volume == revp->fid.volume &&
                                  scp->fid.vnode == revp->fid.vnode &&
                                  scp->fid.unique == revp->fid.unique)
                             ||
@@ -736,6 +783,12 @@ void cm_EndCallbackGrantingCall(cm_scache_t *scp, cm_callbackRequest_t *cbrp,
        if (freeFlag) cm_racingRevokesp = NULL;
 
        lock_ReleaseWrite(&cm_callbackLock);
+
+    if ( serverp ) {
+        lock_ObtainWrite(&cm_serverLock);
+        cm_FreeServer(serverp);
+        lock_ReleaseWrite(&cm_serverLock);
+    }
 }
 
 /* if flags is 1, we want to force the code to make one call, anyway.
@@ -745,50 +798,55 @@ long cm_GetCallback(cm_scache_t *scp, struct cm_user *userp,
        struct cm_req *reqp, long flags)
 {
        long code;
-        cm_conn_t *connp;
-        AFSFetchStatus afsStatus;
-        AFSVolSync volSync;
-        AFSCallBack callback;
-        AFSFid tfid;
-        cm_callbackRequest_t cbr;
-        int mustCall;
-        long sflags;
+    cm_conn_t *connp;
+    AFSFetchStatus afsStatus;
+    AFSVolSync volSync;
+    AFSCallBack callback;
+    AFSFid tfid;
+    cm_callbackRequest_t cbr;
+    int mustCall;
+    long sflags;
+    cm_fid_t sfid;
+
+    osi_Log2(afsd_logp, "GetCallback scp %x flags %lX", scp, flags);
 
 #ifdef AFS_FREELANCE_CLIENT
-       // yj
        // The case where a callback is needed on /afs is handled
        // specially. We need to fetch the status by calling
        // cm_MergeStatus and mark that cm_fakeDirCallback is 2
-       if (cm_freelanceEnabled &&
-          scp->fid.cell==0x1 &&
-               scp->fid.volume==0x20000001 &&
-               scp->fid.unique==0x1 &&
-               scp->fid.vnode==0x1) {
-               // Start by indicating that we're in the process
-               // of fetching the callback
-
-               lock_ObtainMutex(&cm_Freelance_Lock);
-               cm_fakeGettingCallback = 1;
-               lock_ReleaseMutex(&cm_Freelance_Lock);
-
-               // Fetch the status info 
-               cm_MergeStatus(scp, &afsStatus, &volSync, userp, 0);
-
-               // Indicate that the callback is not done
-               lock_ObtainMutex(&cm_Freelance_Lock);
-               cm_fakeDirCallback = 2;
-               // Indicate that we're no longer fetching the callback
-               cm_fakeGettingCallback = 0;
-               lock_ReleaseMutex(&cm_Freelance_Lock);
-
-               return 0;
-       }
+       if (cm_freelanceEnabled) {
+        if (scp->fid.cell==AFS_FAKE_ROOT_CELL_ID &&
+             scp->fid.volume==AFS_FAKE_ROOT_VOL_ID &&
+             scp->fid.unique==0x1 &&
+             scp->fid.vnode==0x1) {
+            
+            // Start by indicating that we're in the process
+            // of fetching the callback
+            lock_ObtainMutex(&cm_Freelance_Lock);
+            osi_Log0(afsd_logp,"cm_getGetCallback fakeGettingCallback=1");
+            cm_fakeGettingCallback = 1;
+            lock_ReleaseMutex(&cm_Freelance_Lock);
+
+            // Fetch the status info 
+            cm_MergeStatus(scp, &afsStatus, &volSync, userp, 0);
+
+            // Indicate that the callback is not done
+            lock_ObtainMutex(&cm_Freelance_Lock);
+            osi_Log0(afsd_logp,"cm_getGetCallback fakeDirCallback=2");
+            cm_fakeDirCallback = 2;
+
+            // Indicate that we're no longer fetching the callback
+            osi_Log0(afsd_logp,"cm_getGetCallback fakeGettingCallback=0");
+            cm_fakeGettingCallback = 0;
+            lock_ReleaseMutex(&cm_Freelance_Lock);
+
+            return 0;
+        }
 
-       /*if (scp->fid.cell==0x1 && scp->fid.volume==0x20000001) {
-               afsi_log("cm_getcallback should NEVER EVER get here... ");
-       }*/
-       // yj: end of getcallback modifications  ---------------
-               
+        if (scp->fid.cell==AFS_FAKE_ROOT_CELL_ID && scp->fid.volume==AFS_FAKE_ROOT_VOL_ID) {
+            osi_Log0(afsd_logp,"cm_getcallback should NEVER EVER get here... ");
+        }
+    }
 #endif /* AFS_FREELANCE_CLIENT */
        
        mustCall = (flags & 1);
@@ -796,66 +854,71 @@ long cm_GetCallback(cm_scache_t *scp, struct cm_user *userp,
        while (1) {
                if (!mustCall && cm_HaveCallback(scp)) return 0;
 
-                /* turn off mustCall, since it has now forced us past the check above */
-                mustCall = 0;
+        /* turn off mustCall, since it has now forced us past the check above */
+        mustCall = 0;
 
-                /* otherwise, we have to make an RPC to get the status */
+        /* otherwise, we have to make an RPC to get the status */
                sflags = CM_SCACHESYNC_FETCHSTATUS | CM_SCACHESYNC_GETCALLBACK;
-                cm_SyncOp(scp, NULL, NULL, NULL, 0, sflags);
-                cm_StartCallbackGrantingCall(scp, &cbr);
+        cm_SyncOp(scp, NULL, NULL, NULL, 0, sflags);
+        cm_StartCallbackGrantingCall(scp, &cbr);
+        sfid = scp->fid;
                lock_ReleaseMutex(&scp->mx);
                
                /* now make the RPC */
                osi_Log1(afsd_logp, "CALL FetchStatus vp %x", (long) scp);
-               do {
-                       code = cm_Conn(&scp->fid, userp, reqp, &connp);
-                       if (code) continue;
+        do {
+                       code = cm_Conn(&sfid, userp, reqp, &connp);
+            if (code) continue;
                
-                       code = RXAFS_FetchStatus(connp->callp, &tfid,
-                               &afsStatus, &callback, &volSync);
+            code = RXAFS_FetchStatus(connp->callp, &tfid,
+                                     &afsStatus, &callback, &volSync);
 
-               } while (cm_Analyze(connp, userp, reqp, &scp->fid, &volSync,
-                                   &cbr, code));
-                code = cm_MapRPCError(code, reqp);
+               } while (cm_Analyze(connp, userp, reqp, &sfid, &volSync, NULL,
+                            &cbr, code));
+        code = cm_MapRPCError(code, reqp);
                osi_Log0(afsd_logp, "CALL FetchStatus DONE");
 
                lock_ObtainMutex(&scp->mx);
-                cm_SyncOpDone(scp, NULL, sflags);
+        cm_SyncOpDone(scp, NULL, sflags);
                if (code == 0) {
-                       cm_EndCallbackGrantingCall(scp, &cbr, &callback, 0);
-                       cm_MergeStatus(scp, &afsStatus, &volSync, userp, 0);
-               }
-                else
-                       cm_EndCallbackGrantingCall(NULL, NULL, NULL, 0);
-
-                /* now check to see if we got an error */
-                if (code) return code;
-        }
+            cm_EndCallbackGrantingCall(scp, &cbr, &callback, 0);
+            cm_MergeStatus(scp, &afsStatus, &volSync, userp, 0);
+               }   
+        else
+            cm_EndCallbackGrantingCall(NULL, &cbr, NULL, 0);
+
+        /* now check to see if we got an error */
+        if (code) return code;
+    }
 }
 
 /* called periodically by cm_daemon to shut down use of expired callbacks */
 void cm_CheckCBExpiration(void)
 {
-       int i;
-        cm_scache_t *scp;
-        long now;
+    int i;
+    cm_scache_t *scp;
+    long now;
         
-       now = osi_Time();
-       lock_ObtainWrite(&cm_scacheLock);
-        for(i=0; i<cm_hashTableSize; i++) {
-               for(scp = cm_hashTablep[i]; scp; scp=scp->nextp) {
-                       scp->refCount++;
-                       lock_ReleaseWrite(&cm_scacheLock);
-                       lock_ObtainMutex(&scp->mx);
-                       if (scp->cbServerp && now > scp->cbExpires) {
-                               cm_DiscardSCache(scp);
-                        }
-                       lock_ReleaseMutex(&scp->mx);
-                       lock_ObtainWrite(&cm_scacheLock);
-                        osi_assert(scp->refCount-- > 0);
-                }
+    osi_Log0(afsd_logp, "CheckCBExpiration");
+
+    now = osi_Time();
+    lock_ObtainWrite(&cm_scacheLock);
+    for(i=0; i<cm_hashTableSize; i++) {
+        for(scp = cm_hashTablep[i]; scp; scp=scp->nextp) {
+            scp->refCount++;
+            lock_ReleaseWrite(&cm_scacheLock);
+            if (scp->cbExpires > 0 && (scp->cbServerp == NULL || now > scp->cbExpires)) {
+                osi_Log1(afsd_logp, "Callback Expiration Discarding SCache scp %x", scp);
+                cm_CallbackNotifyChange(scp);
+                lock_ObtainMutex(&scp->mx);
+                cm_DiscardSCache(scp);
+                lock_ReleaseMutex(&scp->mx);
+            }
+            lock_ObtainWrite(&cm_scacheLock);
+            osi_assert(scp->refCount-- > 0);
         }
-        lock_ReleaseWrite(&cm_scacheLock);
+    }
+    lock_ReleaseWrite(&cm_scacheLock);
 }
 
 /* debug interface: not implemented */
@@ -863,6 +926,7 @@ int SRXAFSCB_GetCellByNum(struct rx_call *a_call, afs_int32 a_cellnum,
                          char **a_name, serverList *a_hosts)
 {
     /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_GetCellByNum - not implemented");
     return RXGEN_OPCODE;
 }
 
@@ -871,5 +935,6 @@ int SRXAFSCB_TellMeAboutYourself(struct rx_call *a_call, afs_int32 a_cellnum,
                           char **a_name, serverList *a_hosts)
 {
     /* XXXX */
+    osi_Log0(afsd_logp, "SRXAFSCB_TellMeAboutYourself - not implemented");
     return RXGEN_OPCODE;
 }