diff --git a/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java b/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java index 4ff4869792..e942d3bebc 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java @@ -145,8 +145,7 @@ public void addServiceListener(String serviceFilterString, ListenerInfo listenerInfo; synchronized ( listenerMap ) { - logger.log(Level.DEBUG, "serviceFilterString: " + serviceFilterString, - null); + logger.log(Level.DEBUG, "serviceFilterString: {0}", null, serviceFilterString); listenerInfo = listenerMap.get( serviceFilterString ); if ( listenerInfo == null ) { diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java index 67786694bf..cf080f697a 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java @@ -56,7 +56,7 @@ public Thread newThread(Runnable r) @Override protected void beforeExecute(Thread t, Runnable r) { - logger.log(Level.DEBUG, "Running task: " + r, null); + logger.log(Level.DEBUG, "Running task: {0}", null, r); } @Override @@ -64,7 +64,7 @@ protected void afterExecute(Runnable r, Throwable t) { if (t != null) { - logger.log(Level.ERROR, "Unexpected problem executing task " + r, t); + logger.log(Level.ERROR, "Unexpected problem executing task {0}", t, r); } } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java index 718c18361c..247e3e0f36 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java @@ -31,6 +31,7 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentMap; import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; @@ -132,9 +133,12 @@ public class ComponentRegistry private final ScheduledExecutorService m_componentActor; + private final UpdateChangeCountProperty m_updateChangeCountPropertyTask; + public ComponentRegistry(final ScrConfiguration scrConfiguration, final ScrLogger logger, final ScheduledExecutorService componentActor ) { m_configuration = scrConfiguration; + m_updateChangeCountPropertyTask = new UpdateChangeCountProperty(m_configuration.serviceChangecountTimeout(), logger, componentActor); m_logger = logger; m_componentActor = componentActor; m_componentHoldersByName = new HashMap<>(); @@ -704,54 +708,119 @@ public void unregisterRegionConfigurationSupport( } - private final AtomicLong changeCount = new AtomicLong(); - - private volatile ServiceRegistration registration; - - public Dictionary getServiceRegistrationProperties() + Dictionary getServiceRegistrationProperties() { - final Dictionary props = new Hashtable<>(); - props.put(PROP_CHANGECOUNT, this.changeCount.get()); - - return props; + return m_updateChangeCountPropertyTask.getServiceRegistrationProperties(); } - public void setRegistration(final ServiceRegistration reg) + public void setRegistration(final ServiceRegistration reg) { - this.registration = reg; + m_updateChangeCountPropertyTask.setRegistration(reg); + m_updateChangeCountPropertyTask.schedule(); } public void updateChangeCount() { - if ( registration != null ) + m_updateChangeCountPropertyTask.updateChangeCount(); + } + + static class UpdateChangeCountProperty implements Runnable { + // TODO 1 seems really low? + private static final long MIN_ALLOWED_DELAY = 1; + private final AtomicLong changeCount = new AtomicLong(); + private volatile ServiceRegistration registration; + private final long maxNumberOfNoChanges; + private final long delay; + private final ScrLogger logger; + private final ScheduledExecutorService executor; + + // guarded by this + private int noChangesCount = 0; + // guarded by this + private ScheduledFuture scheduledFuture = null; + + UpdateChangeCountProperty(long delay, ScrLogger logger, ScheduledExecutorService executor) { - final long count = this.changeCount.incrementAndGet(); + this.logger = logger; + this.executor = executor; + if (delay < MIN_ALLOWED_DELAY) { + logger.log(Level.INFO, + "The service change count timeout {0} is less than the allowable minimum {1}. Using the allowable minimum instead.", null, + delay, MIN_ALLOWED_DELAY); + delay = MIN_ALLOWED_DELAY; + } + this.delay = delay; + // Calculate the max number of no changes; must be at least 1 to avoid missing events + // The calculation is intended to let at least 10 seconds pass before canceling the scheduledFuture + maxNumberOfNoChanges = Long.max(10000 / delay, 1); + } - try - { - m_componentActor.schedule(new Runnable() - { + void setRegistration(ServiceRegistration reg) + { + this.registration = reg; + } - @Override - public void run() - { - if ( changeCount.get() == count ) - { - try - { - registration.setProperties(getServiceRegistrationProperties()); - } - catch ( final IllegalStateException ise) - { - // we ignore this as this might happen on shutdown - } + Dictionary getServiceRegistrationProperties() + { + final Dictionary props = new Hashtable<>(); + props.put(PROP_CHANGECOUNT, this.changeCount.get()); + + return props; + } + + public void updateChangeCount() { + this.changeCount.incrementAndGet(); + schedule(); + } + synchronized void schedule() + { + // reset noChangesCount to ensure task runs at least once more if it exists + noChangesCount = 0; + if (scheduledFuture != null) { + return; + } + scheduledFuture = executor.scheduleWithFixedDelay(this , delay, delay, TimeUnit.MILLISECONDS); + } + + @Override + public void run() + { + ServiceRegistration currentReg = registration; + if (currentReg == null) { + return; + } + try { + Long registeredChangeCount = null; + try { + registeredChangeCount = (Long) currentReg.getReference().getProperty(PROP_CHANGECOUNT); + } catch ( final IllegalStateException ise) { + // we ignore this as this might happen on shutdown + } + if (registeredChangeCount == null || registeredChangeCount.longValue() != changeCount.get()) { + try + { + currentReg.setProperties(getServiceRegistrationProperties()); + } + catch ( final IllegalStateException ise) + { + // we ignore this as this might happen on shutdown + } + } else { + synchronized (this) { + noChangesCount++; + if (noChangesCount > maxNumberOfNoChanges) { + // haven't had any changes for max number of tries; + // cancel the scheduled future if it exists. + if (scheduledFuture != null) { + scheduledFuture.cancel(false); + scheduledFuture = null; } } - }, m_configuration.serviceChangecountTimeout(), TimeUnit.MILLISECONDS); - } - catch (Exception e) { - m_logger.log(Level.WARN, - "Service changecount Timer for {0} had a problem", e, + } + } + } catch (Exception e) { + logger.log(Level.WARN, + "Service changecount update for {0} had a problem", e, registration.getReference()); } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java b/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java index 577823dac2..fcda5059b9 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java @@ -58,8 +58,7 @@ public RegionConfigurationSupport addingService(ServiceReference findMethod(final ComponentLogger logger) throws Invocation // This is 'Debug' however, as the class information, where the search // was conducted, is quite important for the client's own debugging logger.log(Level.DEBUG, - "Locating method " + getMethodName() + " within class " + theClass.getName(), null ); + "Locating method {0} within class {1}", null, getMethodName(), theClass.getName()); } while (true) @@ -177,7 +177,7 @@ private MethodInfo findMethod(final ComponentLogger logger) throws Invocation // Trace as this is going through the whole hierachy and will log for non-existing methods // a lot of lines for e.g. the class Object not containing an activate method logger.log(Level.TRACE, - "Locating method " + getMethodName() + " in class " + theClass.getName(), null ); + "Locating method {0} in class {1}", null, getMethodName(), theClass.getName()); } try @@ -271,7 +271,7 @@ private MethodResult invokeMethod(final Object componentInstance, final P rawPar catch ( IllegalStateException ise ) { rawParameter.getComponentContext().getLogger().log(Level.DEBUG, - ise.getMessage(), null); + ise.getMessage(), ise); return null; } catch ( IllegalAccessException ex ) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java b/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java index 9886894bf3..4775fd41fe 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java @@ -99,7 +99,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Looking for method " + targetClass.getName() + "." + getMethodName(), null ); + "doFindMethod: Looking for method {0}.{1}", null, targetClass.getName(), getMethodName()); } // Case 1 - Service reference parameter @@ -111,8 +111,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}",null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceReference)); } @@ -132,8 +131,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceObjects)); } @@ -153,8 +151,8 @@ protected MethodInfo> doFindMethod( final Class ta { logger.log( Level.DEBUG, - "doFindMethod: No method taking ServiceReference found, checking method taking " - + parameterClass.getName(), null ); + "doFindMethod: No method taking ServiceReference found, checking method taking {0}", + null, parameterClass.getName() ); } // Case 3 - Service object parameter @@ -165,8 +163,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceType)); @@ -185,8 +182,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceType)); @@ -208,7 +204,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_map)); @@ -233,7 +229,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } List paramTypes = new ArrayList<>(2); paramTypes.add(ValueUtils.ValueType.ref_serviceType); @@ -256,7 +252,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } List paramTypes = new ArrayList<>(2); paramTypes.add(ValueUtils.ValueType.ref_serviceType); @@ -352,7 +348,7 @@ else if ( paramType.getName().equals(ClassUtils.FORMATTER_LOGGER_CLASS) ) if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + m, null); + "doFindMethod: Found Method {0}", null, m); } return new MethodInfo<>(m, paramTypes); } @@ -366,8 +362,7 @@ else if (logger.isLogEnabled(Level.WARN)) { logger.log( Level.WARN, - "doFindMethod: Cannot check for methods taking parameter class " + m_referenceClassName + ": " - + targetClass.getName() + " does not see it", null ); + "doFindMethod: Cannot check for methods taking parameter class {0}: {1} does not see it", null, m_referenceClassName, targetClass.getName()); } // if at least one suitable method could be found but none of @@ -481,8 +476,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin { logger.log( Level.DEBUG, - "getServiceObjectAssignableMethod: Checking " + candidateBindMethods.length - + " declared method in class " + targetClass.getName(), null ); + "getServiceObjectAssignableMethod: Checking {0} declared method in class {1}", null, candidateBindMethods.length, targetClass.getName()); } // Iterate over them @@ -492,7 +486,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "getServiceObjectAssignableMethod: Checking " + method, null); + "getServiceObjectAssignableMethod: Checking {0}", null, method); } // Get the parameters for the current method @@ -507,7 +501,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "getServiceObjectAssignableMethod: Considering " + method, null); + "getServiceObjectAssignableMethod: Considering {0}", null, method); } // Get the parameter type @@ -530,8 +524,8 @@ else if (logger.isLogEnabled(Level.DEBUG)) { logger.log( Level.DEBUG, - "getServiceObjectAssignableMethod: Parameter failure: Required " + theParameter + "; actual " - + parameterClass.getName(), null ); + "getServiceObjectAssignableMethod: Parameter failure: Required {0}; actual {1}", + null, theParameter, parameterClass.getName()); } } 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 b8aff475c1..a6864dad87 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 @@ -301,14 +301,16 @@ final boolean isStateLocked() final void dumpThreads() { - try - { - String dump = new ThreadDump().call(); - m_container.getLogger().log(Level.DEBUG, dump, null); - } - catch (Throwable t) - { - m_container.getLogger().log(Level.DEBUG, "Could not dump threads", t); + if (m_container.getLogger().isLogEnabled(Level.DEBUG)) { + try + { + String dump = new ThreadDump().call(); + m_container.getLogger().log(Level.DEBUG, dump, null); + } + catch (Throwable t) + { + m_container.getLogger().log(Level.DEBUG, "Could not dump threads", t); + } } } @@ -832,7 +834,7 @@ final void deactivateInternal(int reason, boolean disable, boolean dispose) if (isFactory() || m_factoryInstance || dispose) { m_container.getLogger().log(Level.DEBUG, - "Disposing component (reason: " + reason + ")", null); + "Disposing component (reason: {0})", null, reason); clear(); } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java index f98601fc9e..9a61a98c55 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java @@ -292,9 +292,8 @@ protected S createImplementationObject( Bundle usingBundle, SetImplementationObj { // we don't need to log the stack trace getLogger().log(Level.ERROR, - "Error during instantiation of the implementation object: " - + ie.getMessage(), - null); + "Error during instantiation of the implementation object: {0}", + null, ie.getMessage()); this.setFailureReason(ie); return null; } diff --git a/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java b/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java new file mode 100644 index 0000000000..ead0dd4ffb --- /dev/null +++ b/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java @@ -0,0 +1,84 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.felix.scr.integration; + +import static org.junit.Assert.assertEquals; +import static org.ops4j.pax.exam.CoreOptions.systemProperty; + +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.ops4j.pax.exam.Configuration; +import org.ops4j.pax.exam.Option; +import org.ops4j.pax.exam.OptionUtils; +import org.ops4j.pax.exam.junit.PaxExam; +import org.osgi.framework.BundleException; +import org.osgi.framework.Constants; +import org.osgi.framework.InvalidSyntaxException; +import org.osgi.framework.ServiceReference; +import org.osgi.service.component.runtime.ServiceComponentRuntime; + +@RunWith(PaxExam.class) +public class GithubPR486Test extends ComponentTestBase +{ + + // test min timeout checking + private static final long DS_SERVICE_CHANGECOUNT_TIMEOUT = 0; + + static + { + descriptorFile = "/integration_test_simple_components.xml"; + // uncomment to enable debugging of this test class + //paxRunnerVmOption = DEBUG_VM_OPTION; + } + + @Configuration + public static Option[] configuration() + { + return OptionUtils.combine(ComponentTestBase.configuration(), + systemProperty( "ds.service.changecount.timeout" ).value( Long.toString(DS_SERVICE_CHANGECOUNT_TIMEOUT) )); + } + + + private ServiceReference scrRef; + @Before + public void addServiceListener() throws InvalidSyntaxException + { + scrRef = bundleContext.getServiceReference(ServiceComponentRuntime.class); + } + + @Test + public void verify_changecount_updates_with_min_timeout() throws InterruptedException, BundleException + { + // Wait a second the changecount timeout`to account for the asynchronous service.changecount property update + Thread.sleep(1000); + + // Check that the service.changecount update was recorded + assertEquals(13L, scrRef.getProperty(Constants.SERVICE_CHANGECOUNT)); + + // Trigger a change by stopping the bundle with components + bundle.stop(); + + // Wait a second the changecount timeout`to account for the asynchronous service.changecount property update + Thread.sleep(1000); + + // Check that another service.changecount update was recorded + assertEquals(26L, scrRef.getProperty(Constants.SERVICE_CHANGECOUNT)); + } +}