incubator-sling-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bdelacre...@apache.org
Subject svn commit: r1367577 - in /sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl: InstallListener.java OsgiInstallerImpl.java tasks/RefreshBundlesTask.java
Date Tue, 31 Jul 2012 14:35:18 GMT
Author: bdelacretaz
Date: Tue Jul 31 14:35:17 2012
New Revision: 1367577

URL: http://svn.apache.org/viewvc?rev=1367577&view=rev
Log:
SLING-2550 - add/tweak DEBUG logs of the installer

Modified:
    sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/InstallListener.java
    sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/OsgiInstallerImpl.java
    sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/tasks/RefreshBundlesTask.java

Modified: sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/InstallListener.java
URL: http://svn.apache.org/viewvc/sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/InstallListener.java?rev=1367577&r1=1367576&r2=1367577&view=diff
==============================================================================
--- sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/InstallListener.java
(original)
+++ sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/InstallListener.java
Tue Jul 31 14:35:17 2012
@@ -77,12 +77,12 @@ public class InstallListener implements 
     public void onEvent(final InstallationEvent event) {
         if ( this.logger.isDebugEnabled() ) {
             if ( event.getType() == InstallationEvent.TYPE.STARTED ) {
-                logger.debug("Notify installer started.");
+                logger.debug("onEvent(STARTED).");
             } else if ( event.getType() == InstallationEvent.TYPE.SUSPENDED ) {
-                logger.debug("Notify installer suspended.");
+                logger.debug("onEvent(SUSPENDED).");
             } else {
                 final TaskResource src = (TaskResource)event.getSource();
-                logger.debug("Notify processed {}", src);
+                logger.debug("onEvent(event.getSource(): {})", src);
             }
         }
         final Object[] listeners = this.tracker.getServices();

Modified: sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/OsgiInstallerImpl.java
URL: http://svn.apache.org/viewvc/sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/OsgiInstallerImpl.java?rev=1367577&r1=1367576&r2=1367577&view=diff
==============================================================================
--- sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/OsgiInstallerImpl.java
(original)
+++ sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/OsgiInstallerImpl.java
Tue Jul 31 14:35:17 2012
@@ -35,6 +35,7 @@ import java.util.Map;
 import java.util.Set;
 import java.util.SortedSet;
 import java.util.TreeSet;
+import java.util.concurrent.atomic.AtomicLong;
 
 import org.apache.sling.commons.osgi.PropertiesUtil;
 import org.apache.sling.installer.api.InstallableResource;
@@ -118,6 +119,7 @@ public class OsgiInstallerImpl
     private final Object resourcesLock = new Object();
 
     private final InstallListener listener;
+    private final AtomicLong backgroundTaskCounter = new AtomicLong();
 
 
     /** Constructor */
@@ -136,6 +138,7 @@ public class OsgiInstallerImpl
     public void deactivate() {
         // wake up sleeping thread
         synchronized (this.resourcesLock) {
+            logger.debug("Deactivating and notifying resourcesLock");
             this.active = false;
             this.resourcesLock.notify();
         }
@@ -147,7 +150,13 @@ public class OsgiInstallerImpl
         this.listener.dispose();
 
         if ( this.backgroundThread != null ) {
-            this.logger.debug("Waiting for installer thread to stop");
+            if(logger.isDebugEnabled()) {
+                try {
+                    logger.debug("Waiting for main background thread {} to stop", backgroundThread.getName());
+                } catch(NullPointerException ignore) {
+                }
+            }
+            
             while ( this.backgroundThread != null ) {
                 // use a local variable to avoid NPEs
                 final Thread t = this.backgroundThread;
@@ -159,6 +168,7 @@ public class OsgiInstallerImpl
                     }
                 }
             }
+            logger.debug("Done waiting for background thread");
         }
 
         // remove file util
@@ -197,12 +207,13 @@ public class OsgiInstallerImpl
      * @see java.lang.Runnable#run()
      */
     public void run() {
+        logger.debug("Main background thread starts");
         try {
             this.init();
 
             this.listener.start();
             while (this.active) {
-                this.logger.debug("Running new installer cycle");
+                this.logger.debug("Starting new installer cycle");
 
                 // merge potential new resources
                 this.mergeNewlyRegisteredResources();
@@ -223,18 +234,25 @@ public class OsgiInstallerImpl
                         if ( !this.hasNewResources() && this.active && !this.retryDuringTaskExecution)
{
                             // No tasks to execute - wait until new resources are
                             // registered
-                            logger.debug("No tasks to process, going idle");
+                            logger.debug("No more tasks to process, suspending listener and
going idle");
                             this.listener.suspend();
+                            
                             try {
+                                logger.debug("wait() on resourcesLock");
                                 this.resourcesLock.wait();
                             } catch (final InterruptedException ignore) {}
+                            
                             if ( active ) {
+                                logger.debug("Done wait()ing on resourcesLock, restarting
listener");
                                 this.listener.start();
+                            } else {
+                                logger.debug("Done wait()ing on resourcesLock, but active={},
listener won't be restarted now", active);
                             }
                         }
                     }
                 } else if ( action == ACTION.SHUTDOWN ) {
                     // stop processing
+                    logger.debug("Action is SHUTDOWN, going inactive");
                     this.active = false;
                 }
 
@@ -243,12 +261,14 @@ public class OsgiInstallerImpl
         } finally {
             this.backgroundThread = null;
         }
+        logger.debug("Main background thread ends");
     }
 
     /**
      * Wake up the run cycle.
      */
     private void wakeUp() {
+        logger.debug("wakeUp called");
         this.listener.start();
         synchronized (this.resourcesLock) {
             this.resourcesLock.notify();
@@ -292,7 +312,7 @@ public class OsgiInstallerImpl
                     createdResources.add(rr);
                     logger.debug("Registering new resource: {}", rr);
                 } catch (final IOException ioe) {
-                    logger.warn("Cannot create internal resource (resource will be ignored):"
+ r, ioe);
+                    logger.warn("Cannot create InternalResource (resource will be ignored):"
+ r, ioe);
                 }
             }
         }
@@ -430,10 +450,6 @@ public class OsgiInstallerImpl
         }
     }
 
-    /**
-     * This is the heart of the installer.
-     * It processes the rendezvous between a resource provider and available resources.
-     */
     private void mergeNewlyRegisteredResources() {
         synchronized ( this.resourcesLock ) {
             for(final Map.Entry<String, List<InternalResource>> entry : this.newResourcesSchemes.entrySet())
{
@@ -491,9 +507,8 @@ public class OsgiInstallerImpl
     }
 
     /**
-     * This is the heart of the installer -
-     * it processes new resources and deleted resources and
-     * merges them with existing resources.
+     * Process new resources and deleted resources and
+     * merge them with existing resources.
      */
     private void mergeNewResources() {
         // if we have new resources we have to sync them
@@ -521,24 +536,24 @@ public class OsgiInstallerImpl
         if ( !logger.isDebugEnabled() ) {
             return;
         }
+        int counter = 0;
         final StringBuilder sb = new StringBuilder();
         sb.append(hint);
         sb.append(" Resources={\n");
         for(final String id : this.persistentList.getEntityIds() ) {
-            sb.append("- ");
+            sb.append("- ").append(hint).append(" RegisteredResource ");
             sb.append(id);
-            sb.append(" : [");
-            boolean first = true;
+            sb.append("\n    RegisteredResource.info=[");
+            String sep = "";
             for(final RegisteredResource rr : this.persistentList.getEntityResourceList(id).getResources())
{
-                if ( !first) {
-                    sb.append(", ");
-                }
-                first = false;
+                sb.append(sep);
+                sep=", ";
                 sb.append(rr);
+                counter++;
             }
             sb.append("]\n");
         }
-        sb.append("}\n");
+        sb.append("} (").append(hint).append("): ").append(counter).append(" RegisteredResources\n");
         logger.debug(sb.toString());
     }
 
@@ -600,7 +615,7 @@ public class OsgiInstallerImpl
             final InstallationContext ctx = new InstallationContext() {
 
                 public void addTaskToNextCycle(final InstallTask t) {
-                    logger.warn("Deprecated method addTaskToNextCycle is called. Task is
executed in this cycle(!): {}", t);
+                    logger.warn("Deprecated method addTaskToNextCycle was called. Task will
be executed in this cycle instead: {}", t);
                     synchronized ( tasks ) {
                         tasks.add(t);
                     }
@@ -615,7 +630,7 @@ public class OsgiInstallerImpl
 
                 public void addAsyncTask(final InstallTask t) {
                     if ( t.isAsynchronousTask() ) {
-                        logger.warn("Deprecated method addAsyncTask is called: {}", t);
+                        logger.warn("Deprecated method addAsyncTask was called: {}", t);
                         this.addTaskToCurrentCycle(t);
                     } else {
                         logger.warn("Deprecated method addAsyncTask is called with non async
task(!): {}", t);
@@ -630,14 +645,18 @@ public class OsgiInstallerImpl
                 public void asyncTaskFailed(final InstallTask t) {
                     // persist all changes and retry restart
                     // remove attribute
+                    logger.debug("asyncTaskFailed: {}", t);
                     if ( t.getResource() != null ) {
                         t.getResource().setAttribute(InstallTask.ASYNC_ATTR_NAME, null);
                     }
                     persistentList.save();
                     synchronized ( resourcesLock ) {
                         if ( !active ) {
+                            logger.debug("Restarting background thread from asyncTaskFailed");
                             active = true;
                             startBackgroundThread();
+                        } else {
+                            logger.debug("active={}, no need to restart background thread",
active);
                         }
                     }
                 }
@@ -668,10 +687,14 @@ public class OsgiInstallerImpl
                     // save new state
                     this.cleanupInstallableResources();
                     final InstallTask aSyncTask = task;
-                    final Thread t = new Thread() {
+                    final String threadName = "BackgroundTaskThread" + backgroundTaskCounter.incrementAndGet();
+                    final Thread t = new Thread(threadName) {
 
                         @Override
                         public void run() {
+                            logger.debug("Starting background thread {} to execute {}", 
+                                    Thread.currentThread().getName(), 
+                                    aSyncTask);
                             try {
                                 Thread.sleep(2000L);
                             } catch (final InterruptedException ie) {
@@ -682,6 +705,7 @@ public class OsgiInstallerImpl
                                 aSyncTask.getResource().setAttribute(InstallTask.ASYNC_ATTR_NAME,
oldValue);
                             }
                             aSyncTask.execute(ctx);
+                            logger.debug("Background thread {} ends",  Thread.currentThread().getName());

                         }
                     };
                     t.start();
@@ -712,6 +736,7 @@ public class OsgiInstallerImpl
         final boolean result = this.persistentList.compact();
         this.persistentList.save();
         printResources("Compacted");
+        logger.debug("cleanupInstallableResources returns {}", result);
         return result;
     }
 
@@ -771,6 +796,7 @@ public class OsgiInstallerImpl
      * @see org.apache.sling.installer.api.tasks.RetryHandler#scheduleRetry()
      */
     public void scheduleRetry() {
+        logger.debug("scheduleRetry called");
         this.listener.start();
         synchronized ( this.resourcesLock ) {
             this.retryDuringTaskExecution = true;

Modified: sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/tasks/RefreshBundlesTask.java
URL: http://svn.apache.org/viewvc/sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/tasks/RefreshBundlesTask.java?rev=1367577&r1=1367576&r2=1367577&view=diff
==============================================================================
--- sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/tasks/RefreshBundlesTask.java
(original)
+++ sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl/tasks/RefreshBundlesTask.java
Tue Jul 31 14:35:17 2012
@@ -78,7 +78,7 @@ public class RefreshBundlesTask
             for(final Long id : BUNDLE_IDS) {
                 final Bundle b = this.getBundleContext().getBundle(id);
                 if ( b != null ) {
-                    getLogger().debug("Refreshing bundle {}", b);
+                    getLogger().debug("Will refresh bundle {}", b);
                     bundles.add(b);
                 } else {
                     getLogger().debug("Unable to refresh bundle {} - already gone.", id);
@@ -87,7 +87,7 @@ public class RefreshBundlesTask
             BUNDLE_IDS.clear();
         }
         if ( bundles.size() > 0 ) {
-            ctx.log("Refreshing bundles {}", bundles);
+            ctx.log("Refreshing {} bundles: {}", bundles.size(), bundles);
             this.refreshEventCount = -1;
             this.getBundleContext().addFrameworkListener(this);
             try {
@@ -97,13 +97,15 @@ public class RefreshBundlesTask
                 do {
                     synchronized ( this ) {
                         try {
+                            ctx.log("Waiting up to {} seconds for bundles refresh", MAX_REFRESH_PACKAGES_WAIT_SECONDS);
                             this.wait(MAX_REFRESH_PACKAGES_WAIT_SECONDS * 1000);
                         } catch (final InterruptedException ignore) {
                             // ignore
                         }
                         if ( start + MAX_REFRESH_PACKAGES_WAIT_SECONDS * 1000 < System.currentTimeMillis()
) {
                             this.getLogger().warn("No FrameworkEvent.PACKAGES_REFRESHED event
received within {}"
-                                            + " seconds after refresh.", MAX_REFRESH_PACKAGES_WAIT_SECONDS);
+                                            + " seconds after refresh, aborting wait.", 
+                                            MAX_REFRESH_PACKAGES_WAIT_SECONDS);
                             this.refreshEventCount++;
                         }
                     }
@@ -111,6 +113,7 @@ public class RefreshBundlesTask
             } finally {
                 this.getBundleContext().removeFrameworkListener(this);
             }
+            ctx.log("Done refreshing {} bundles", bundles.size());
         }
 	}
 



Mime
View raw message