FELIX-3991 Fix, javadoc, and log return values for RegistrationManager.  Also add and improve some logging

git-svn-id: https://svn.apache.org/repos/asf/felix/trunk@1460261 13f79535-47bb-0310-9956-ffa450edef68
diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java
index 5027009..7f78903 100644
--- a/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java
+++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java
@@ -826,7 +826,7 @@
     {
         if ( m_dependenciesCollected)
         {
-            log( LogService.LOG_DEBUG, "dependency map already present, do not collect dependencies", null );
+            log( LogService.LOG_DEBUG, "dependencies already collected, do not collect dependencies", null );
             return false;
         }
         initDependencyManagers();
@@ -835,9 +835,9 @@
             if ( !dependencyManager.prebind() )
             {
                 //not actually satisfied any longer
-                returnServices();
+                deactivateDependencyManagers();
                 log( LogService.LOG_DEBUG, "Could not get required dependency for dependency manager: {0}",
-                        new Object[] {dependencyManager}, null );
+                        new Object[] {dependencyManager.getName()}, null );
                 throw new IllegalStateException( "Missing dependencies, not satisfied" );
             }
         }
@@ -846,19 +846,11 @@
         return true;
     }
 
-    protected void unsetDependencyMap()
+    protected void unsetDependenciesCollected()
     {
         m_dependenciesCollected = false;
     }
 
-    private void returnServices()
-    {
-        for ( DependencyManager<S, ?> dependencyManager : m_dependencyManagers )
-        {
-            dependencyManager.deactivate();
-        }
-    }
-
     abstract <T> void update( DependencyManager<S, T> dependencyManager, RefPair<T> refPair, int trackingCount );
 
     abstract <T> void invokeBindMethod( DependencyManager<S, T> dependencyManager, RefPair<T> refPair, int trackingCount );
@@ -1080,7 +1072,8 @@
 
     private void deactivateDependencyManagers()
     {
-        for ( DependencyManager dm: getDependencyManagers() )
+        log( LogService.LOG_DEBUG, "Deactivating dependency managers", null);
+        for ( DependencyManager<S, ?> dm: getDependencyManagers() )
         {
             dm.deactivate();
         }
@@ -1088,7 +1081,8 @@
 
     private void disableDependencyManagers()
     {
-        for ( DependencyManager dm: getDependencyManagers() )
+        log( LogService.LOG_DEBUG, "Disabling dependency managers", null);
+        for ( DependencyManager<S, ?> dm: getDependencyManagers() )
         {
             dm.unregisterServiceListener();
         }
@@ -1311,6 +1305,7 @@
             {
                 if ( !acm.unregisterService() )
                 {
+                    acm.log( LogService.LOG_DEBUG, "Component deactivation occuring on another thread", null );
                     //another thread is deactivating.
                     return;
                 }
@@ -1323,7 +1318,7 @@
                     {
                         acm.disableDependencyManagers();
                     }
-                    acm.unsetDependencyMap();
+                    acm.unsetDependenciesCollected();
                 }
                 finally
                 {
@@ -1338,9 +1333,6 @@
 
         void doDisable( AbstractComponentManager acm )
         {
-            // dispose and recreate dependency managers
-//            acm.disableDependencyManagers();
-
             // reset the component id now (a disabled component has none)
             acm.unregisterComponentId();
         }
@@ -1539,7 +1531,8 @@
 
         void deactivate( AbstractComponentManager acm, int reason, boolean disable )
         {
-            acm.log( LogService.LOG_DEBUG, "Deactivating component", null );
+            acm.log( LogService.LOG_DEBUG, "Deactivating component in state Unsatisfied for reason {0}: disable: {1}",
+                    new Object[] {reason, disable}, null );
 
             // catch any problems from deleting the component to prevent the
             // component to remain in the deactivating state !
diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/DependencyManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/DependencyManager.java
index e0035b0..9f6bf23 100644
--- a/scr/src/main/java/org/apache/felix/scr/impl/manager/DependencyManager.java
+++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/DependencyManager.java
@@ -175,6 +175,7 @@
         public void setTracker( ServiceTracker<T, RefPair<T>> tracker )
         {
             trackerRef.set( tracker );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracker reset (closed)", new Object[] {getName()}, null );
             trackerOpened = false;
         }
 
@@ -210,6 +211,7 @@
         public void setTrackerOpened()
         {
             trackerOpened = true;
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracker opened", new Object[] {getName()}, null );
         }
 
         protected Map<ServiceReference<T>, RefPair<T>> getPreviousRefMap()
@@ -321,7 +323,7 @@
 
         public void addedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic added {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic added {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
         	boolean tracked = false;
             if ( getPreviousRefMap().remove( serviceReference ) == null )
             {
@@ -342,7 +344,7 @@
                     m_componentManager.activateInternal( trackingCount );
                 }
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic added {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic added {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if ( !tracked )
             {
 				tracked(trackingCount);
@@ -351,25 +353,25 @@
 
         public void modifiedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic modified {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic modified {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if (isActive())
             {
                 m_componentManager.update( DependencyManager.this, refPair, trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic modified {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic modified {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
         }
 
         public void removedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if ( isActive() )
             {
                 boolean unbind = isOptional() || !getTracker().isEmpty();
                 if ( unbind )
                 {
                     m_componentManager.invokeUnbindMethod( DependencyManager.this, refPair, trackingCount );
-                    m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (unbind) {2}", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+                    m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (unbind) {2}", new Object[] {getName(), trackingCount, serviceReference}, null );
                     tracked( trackingCount );
                 }
                 else
@@ -379,12 +381,12 @@
                     tracked( trackingCount );
                     m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
                     lastRefPair = null;
-                    m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (deactivate) {2}", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+                    m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (deactivate) {2}", new Object[] {getName(), trackingCount, serviceReference}, null );
                 }
             }
             else
             {
-                m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (inactive) {2}", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+                m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleDynamic removed (inactive) {2}", new Object[] {getName(), trackingCount, serviceReference}, null );
                 tracked( trackingCount );
             }
             ungetService( refPair );
@@ -457,13 +459,13 @@
 
         public void addedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy added {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy added {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
             if (isActive())
             {
                 m_componentManager.log( LogService.LOG_DEBUG,
                         "Dependency Manager: Static dependency on {0}/{1} is broken", new Object[]
-                        {m_dependencyMetadata.getName(), m_dependencyMetadata.getInterface()}, null );
+                        {getName(), m_dependencyMetadata.getInterface()}, null );
                 m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
                 m_componentManager.activateInternal( trackingCount );
 
@@ -472,37 +474,37 @@
             {
                 m_componentManager.activateInternal( trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy added {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy added {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public void modifiedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy modified {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy modified {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if (isActive())
             {
                 m_componentManager.update( DependencyManager.this, refPair, trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy modified {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy modified {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
         }
 
         public void removedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy removed {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy removed {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
             if ( isActive() )
             {
                 //deactivate while ref is still tracked
                 m_componentManager.log( LogService.LOG_DEBUG,
                         "Dependency Manager: Static dependency on {0}/{1} is broken", new Object[]
-                        {m_dependencyMetadata.getName(), m_dependencyMetadata.getInterface()}, null );
+                        {getName(), m_dependencyMetadata.getInterface()}, null );
                 m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
                 //try to reactivate after ref is no longer tracked.
                 m_componentManager.activateInternal( trackingCount );
             }
             //This is unlikely
             ungetService( refPair );
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy removed {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticGreedy removed {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public boolean open()
@@ -553,29 +555,29 @@
 
         public void addedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant added {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant added {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
             if ( isTrackerOpened() && !isOptional() && !isActive())
             {
                 m_componentManager.activateInternal( trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant added {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant added {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public void modifiedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant modified {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant modified {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if (isActive())
             {
                 m_componentManager.update( DependencyManager.this, refPair, trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant modified {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant modified {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
         }
 
         public void removedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant removed {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant removed {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
             if ( isActive() )
             {
@@ -584,7 +586,7 @@
                     //we are tracking the used refs, so we can deactivate here.
                     m_componentManager.log( LogService.LOG_DEBUG,
                         "Dependency Manager: Static dependency on {0}/{1} is broken", new Object[]
-                            { m_dependencyMetadata.getName(), m_dependencyMetadata.getInterface() }, null );
+                            { getName(), m_dependencyMetadata.getInterface() }, null );
                     m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
 
                     // FELIX-2368: immediately try to reactivate
@@ -593,7 +595,7 @@
                 }
             }
             ungetService( refPair );
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant removed {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} MultipleStaticReluctant removed {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public boolean open()
@@ -648,7 +650,7 @@
 
         public void addedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic added {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic added {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
         	boolean tracked = false;
             if ( getPreviousRefMap().remove( serviceReference ) == null )
             {
@@ -684,7 +686,7 @@
                 }
             }
             this.trackingCount = trackingCount;
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic added {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic added {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if ( !tracked )
             {
 				tracked(trackingCount);
@@ -693,19 +695,19 @@
 
         public void modifiedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic modified {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic modified {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if (isActive())
             {
                 m_componentManager.update( DependencyManager.this, refPair, trackingCount );
             }
             this.trackingCount = trackingCount;
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic modified {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic modified {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
         }
 
         public void removedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic removed {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic removed {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if (refPair == this.refPair)
             {
                 if ( isActive() )
@@ -758,7 +760,7 @@
                 this.trackingCount = trackingCount;
                 tracked( trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic removed {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleDynamic removed {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public boolean open()
@@ -821,7 +823,7 @@
 
         public void addedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic added {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic added {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             this.trackingCount = trackingCount;
             tracked( trackingCount );
             if ( isActive() )
@@ -831,29 +833,37 @@
                     m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
                     m_componentManager.activateInternal( trackingCount );
                 }
+                else 
+                {
+                    m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic active but new {2} is worse match than old {3}", new Object[] {getName(), trackingCount, refPair, this.refPair, }, null );               
+                }
             }
             else if (isTrackerOpened() && !isOptional() )
             {
                 m_componentManager.activateInternal( trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic added {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            else 
+            {
+                m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic active: {2} trackerOpened: {3} optional: {4}", new Object[] {getName(), trackingCount, isActive(), isTrackerOpened(), isOptional()}, null );               
+            }
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic added {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public void modifiedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic modified {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic modified {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             if ( isActive() )
             {
                 m_componentManager.update( DependencyManager.this, refPair, trackingCount );
             }
             this.trackingCount = trackingCount;
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic modified {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic modified {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
             tracked( trackingCount );
         }
 
         public void removedService( ServiceReference<T> serviceReference, RefPair<T> refPair, int trackingCount )
         {
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic removed {2} (enter)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic removed {2} (enter)", new Object[] {getName(), trackingCount, serviceReference}, null );
             this.trackingCount = trackingCount;
             tracked( trackingCount );
             if ( isActive() && refPair == this.refPair )
@@ -861,7 +871,7 @@
                 m_componentManager.deactivateInternal( ComponentConstants.DEACTIVATION_REASON_REFERENCE, false, trackingCount );
                 m_componentManager.activateInternal( trackingCount );
             }
-            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic removed {2} (exit)", new Object[] {m_dependencyMetadata.getName(), trackingCount, serviceReference}, null );
+            m_componentManager.log( LogService.LOG_DEBUG, "dm {0} tracking {1} SingleStatic removed {2} (exit)", new Object[] {getName(), trackingCount, serviceReference}, null );
         }
 
         public boolean open()
@@ -1220,7 +1230,7 @@
             // or if there is a service reference cycle involving service
             // factories !
             m_componentManager.log( LogService.LOG_ERROR, "Failed getting service {0} ({1}/{2,number,#})", new Object[]
-                { m_dependencyMetadata.getName(), m_dependencyMetadata.getInterface(),
+                { getName(), m_dependencyMetadata.getInterface(),
                     refPair.getRef().getProperty( Constants.SERVICE_ID ) }, e );
             return null;
         }
@@ -1294,7 +1304,7 @@
         {
             m_componentManager.log( LogService.LOG_DEBUG,
                 "For dependency {0}, no longer satisfied, bind fails",
-                new Object[]{ m_dependencyMetadata.getName() }, null );
+                new Object[]{ getName() }, null );
             return false;
         }
 
@@ -1320,7 +1330,7 @@
         }
         m_componentManager.log( LogService.LOG_DEBUG,
             "For dependency {0}, optional: {1}; to bind: {2}",
-            new Object[]{ m_dependencyMetadata.getName(), success, refs }, null );
+            new Object[]{ getName(), success, refs }, null );
         for ( RefPair<T> refPair : refs )
         {
             if ( !refPair.isFailed() )
@@ -1329,7 +1339,7 @@
                 {
                     m_componentManager.log( LogService.LOG_DEBUG,
                             "For dependency {0}, failed to invoke bind method on object {1}",
-                            new Object[] {m_dependencyMetadata.getName(), refPair}, null );
+                            new Object[] {getName(), refPair}, null );
 
                 }
                 success = true;
@@ -1371,8 +1381,8 @@
         }
 
         m_componentManager.log( LogService.LOG_DEBUG,
-                "DependencyManager : close {0} for {1} at tracking count {2} refpairs: {3}",
-                new Object[] {this, componentInstance, trackingCount.get(), refPairs}, null );
+                "DependencyManager: {0} close component unbinding from {1} at tracking count {2} refpairs: {3}",
+                new Object[] {getName(), componentInstance, trackingCount.get(), refPairs}, null );
         m_componentManager.waitForTracked( trackingCount.get() );
         for ( RefPair<T> boundRef : refPairs )
         {
@@ -1381,11 +1391,6 @@
                 invokeUnbindMethod( componentInstance, boundRef, trackingCount.get() );
             }
 
-            // unget the service, we call it here since there might be a
-            // bind method (or the locateService method might have been
-            // called) but there is no unbind method to actually unbind
-            // the service (see FELIX-832)
-//                ungetService( boundRef );
         }
         latch.countDown();
     }
@@ -1740,7 +1745,7 @@
         if ( ( m_target == null && target == null ) || ( m_target != null && m_target.equals( target ) ) )
         {
             m_componentManager.log( LogService.LOG_DEBUG, "No change in target property for dependency {0}: currently registered: {1}", new Object[]
-                    {m_dependencyMetadata.getName(), registered}, null );
+                    {getName(), registered}, null );
             if (registered)
             {
                 return;
@@ -1763,7 +1768,7 @@
             refMap = new TreeMap<ServiceReference<T>, RefPair<T>>(Collections.reverseOrder());
         }
         m_componentManager.log( LogService.LOG_DEBUG, "Setting target property for dependency {0} to {1}", new Object[]
-                {m_dependencyMetadata.getName(), target}, null );
+                {getName(), target}, null );
         try
         {
             m_targetFilter = m_componentManager.getActivator().getBundleContext().createFilter( filterString );
@@ -1771,7 +1776,7 @@
         catch ( InvalidSyntaxException ise )
         {
             m_componentManager.log( LogService.LOG_ERROR, "Invalid syntax in target property for dependency {0} to {1}", new Object[]
-                    {m_dependencyMetadata.getName(), target}, null );
+                    {getName(), target}, null );
             // TODO this is an error, how do we recover?
             m_targetFilter = null;
         }
@@ -1784,6 +1789,8 @@
         final ServiceTracker<T, RefPair<T>> oldTracker = trackerRef.get();
         customizer.setPreviousRefMap( refMap );
         boolean initialActive = oldTracker != null && oldTracker.isActive();
+        m_componentManager.log( LogService.LOG_INFO, "New service tracker for {0}, initial active: {1}", new Object[]
+                {getName(), initialActive}, null );
         ServiceTracker<T, RefPair<T>> tracker = new ServiceTracker<T, RefPair<T>>( m_componentManager.getActivator().getBundleContext(), m_targetFilter, customizer, initialActive );
         customizer.setTracker( tracker );
         registered = true;
@@ -1794,7 +1801,7 @@
             oldTracker.completeClose( refMap );
         }
         m_componentManager.log( LogService.LOG_DEBUG, "registering service listener for dependency {0}", new Object[]
-                {m_dependencyMetadata.getName()}, null );
+                {getName()}, null );
     }
 
     private Customizer<T> newCustomizer()
@@ -1804,7 +1811,7 @@
         {
             customizer = new NoPermissionsCustomizer();
             m_componentManager.log( LogService.LOG_INFO, "No permission to get services for {0}", new Object[]
-                    {m_dependencyMetadata.getName()}, null );
+                    {getName()}, null );
         }
         else if (m_componentManager.isFactory())
         {
@@ -1858,7 +1865,7 @@
         }
         registered = false;
         m_componentManager.log( LogService.LOG_DEBUG, "unregistering service listener for dependency {0}", new Object[]
-                {m_dependencyMetadata.getName()}, null );
+                {getName()}, null );
         return refMap;
     }
 
@@ -1878,6 +1885,6 @@
 
     public String toString()
     {
-        return "DependencyManager: Component [" + m_componentManager + "] reference [" + m_dependencyMetadata.getName() + "]";
+        return "DependencyManager: Component [" + m_componentManager + "] reference [" + getName() + "]";
     }
 }
diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/ImmediateComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/ImmediateComponentManager.java
index 05b2083..daf4583 100644
--- a/scr/src/main/java/org/apache/felix/scr/impl/manager/ImmediateComponentManager.java
+++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/ImmediateComponentManager.java
@@ -168,11 +168,11 @@
         if ( m_implementationObject != null )
         {
             S implementationObject = m_implementationObject;
-            disposeImplementationObject( implementationObject, m_componentContext, reason );
             m_useCount.set( 0 );
             m_implementationObject = null;
+            disposeImplementationObject( implementationObject, m_componentContext, reason );
             cleanupImplementationObject( implementationObject );
-            log( LogService.LOG_DEBUG, "Unset implementation object for component {0} in deleteComponent for reason {1}", new Object[] { getName(), REASONS[ reason ] },  null );
+            log( LogService.LOG_DEBUG, "Unset and deconfigured implementation object for component {0} in deleteComponent for reason {1}", new Object[] { getName(), REASONS[ reason ] },  null );
             m_componentContext = null;
             m_properties = null;
             m_serviceProperties = null;
@@ -336,8 +336,6 @@
             md.close( implementationObject );
         }
 
-        // 3. Release all references
-        // nothing to do, we keep no references on per-Bundle services
     }
 
     protected void cleanupImplementationObject( Object implementationObject )
@@ -788,7 +786,7 @@
                     if ( m_useCount.get() == 0 )
                     {
                         state().ungetService( this );
-                        unsetDependencyMap();
+                        unsetDependenciesCollected();
                     }
                 }
                 finally
diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/RegistrationManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/RegistrationManager.java
index 76a9fa2..b14202e 100644
--- a/scr/src/main/java/org/apache/felix/scr/impl/manager/RegistrationManager.java
+++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/RegistrationManager.java
@@ -79,9 +79,10 @@
     private volatile T m_serviceRegistration;
     /**
      * 
-     * @param desired
-     * @param services TODO
-     * @return true if this thread reached the requested state
+     * @param desired desired registration state
+     * @param services services to register this under
+     * @return true if this request results in a state change, false if we are already in the desired state or some other thread 
+     * will deal with the consequences of the state change.
      */
     boolean changeRegistration( RegState desired, String[] services )
     {
@@ -93,19 +94,25 @@
             {
                 if ((desired == RegState.unregistered) == (m_serviceRegistration == null))
                 {
-                    return false; //already in desired state
+                    log( LogService.LOG_DEBUG, "Already in desired state {0}", new Object[]
+                            {desired}, null );
+                    return false; 
                 }
             }
             else if (opqueue.get( opqueue.size() - 1 ).getRegState() == desired)
             {
+                log( LogService.LOG_DEBUG, "Duplicate request on other thread: registration change queue {0}", new Object[]
+                        {opqueue}, null );
                 rsw = opqueue.get( opqueue.size() - 1 );
-                return false; //another thread will do our work.
+                return false; //another thread will do our work and owns the state change
             }
             rsw = new RegStateWrapper( desired );
             opqueue.add( rsw );
             if (opqueue.size() > 1)
             {
-                return false; //some other thread will do it later
+                log( LogService.LOG_DEBUG, "Allowing other thread to process request: registration change queue {0}", new Object[]
+                        {opqueue}, null );
+                return true; //some other thread will do it later but this thread owns the state change.
             }
             //we're next
             do
diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/ServiceFactoryComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/ServiceFactoryComponentManager.java
index 2dd097e..8df7ae7 100644
--- a/scr/src/main/java/org/apache/felix/scr/impl/manager/ServiceFactoryComponentManager.java
+++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/ServiceFactoryComponentManager.java
@@ -205,7 +205,7 @@
         if ( serviceContexts.isEmpty() && getState() == STATE_ACTIVE )
         {
             changeState( Registered.getInstance() );
-            unsetDependencyMap();
+            unsetDependenciesCollected();
         }
     }