You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@sling.apache.org by bd...@apache.org on 2012/07/31 16:35:18 UTC
svn commit: r1367577 - in
/sling/trunk/installer/core/src/main/java/org/apache/sling/installer/core/impl:
InstallListener.java OsgiInstallerImpl.java tasks/RefreshBundlesTask.java
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());
}
}