Environment Service Missing

[MLausberg]

Description

We created an application based on Eclipse 2023-06 (4.28).
The very first time we start the application the log4j2 logic is initialized correctly and we can see log messages.
But after closing the application the following start commands will not initialize log4j2 correctly and fail.
No exyception is shown and no log messages are created anymore.

From second time on, log4j is using a default implementation for all logger variables.

it seems that the services which provide Environment variable information are not registeed correctly when initializing/calling
org.apache.logging.log4j.util.PropertiesUtil$Environment

sources.add(propertySource);
// We don't log anything on the status logger.
ServiceLoaderUtil.loadServices(PropertySource.class, MethodHandles.lookup(), false, false).forEach(sources::add);

While initializing log4j2, the System properties are not available and thats why our *.xml is not fetched
-Dlog4j2.debug=true
-DLog4jContextSelector=org.apache.logging.log4j.core.selector.BasicContextSelector
-Dlog4j2.configurationFile=file:log4j2.xml

from bundle.info
org.apache.logging.log4j.1.2-api,2.20.0,plugins/org.apache.logging.log4j.1.2-api_2.20.0.jar,4,false
org.apache.logging.log4j.api,2.20.0,plugins/org.apache.logging.log4j.api_2.20.0.jar,3,true
org.apache.logging.log4j.core,2.20.0,plugins/org.apache.logging.log4j.core_2.20.0.jar,3,true
org.apache.logging.log4j.jcl,2.20.0,plugins/org.apache.logging.log4j.jcl_2.20.0.jar,4,false
org.apache.logging.log4j.slf4j-impl,2.20.0,plugins/org.apache.logging.log4j.slf4j-impl_2.20.0.jar,4,false

Configuration

Version: [Log4j version]
org.apache.logging.log4j.1.2-api_2.20.0
org.apache.logging.log4j.api_2.20.0
org.apache.logging.log4j.core_2.20.0
org.apache.logging.log4j.jcl_2.20.0
org.apache.logging.log4j.slf4j-impl_2.20.0

Operating system: [OS and version]
org.osgi.framework.os.name = Windows10
osgi.ws = win32
sun.arch.data.model = 64

JDK: [JDK distribution and version]
Eclipse Adoptium Temurin-17.0.8+7

Logs

Can not provide any logs, because they ar emissing.
We assume a plugin loading order issue or a service registration problem.

WARN StatusConsoleListener No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property 'log4j2.debug' to show Log4j 2 internal initialization logging. See https://logging.apache.org/log4j/2.x/manual/configuration.html for instructions on how to configure Log4j 2
WARN StatusConsoleListener No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property 'log4j2.debug' to show Log4j 2 internal initialization logging. See https://logging.apache.org/log4j/2.x/manual/configuration.html for instructions on how to configure Log4j 2

Reproduction

[ppkarwasz]

@MLausberg,

Can you check with our 2.20.1-SNAPSHOT? There has been at least one improvement for OSGI applications (#1367), since the release of 2.20.0, which concerned ServiceLoaderUtil (this component loads all property sources including the one for Java system properties).

[MLausberg]

I have downloaded and replaced the jars in the application
log4j-1.2-api-2.20.1-20230825.123921-76
log4j-api-2.20.1-20230825.123921-76
log4j-core-2.20.1-20230825.123921-76
log4j-jcl-2.20.1-20230825.123921-76

The error is still the same.

I was not able to debug the 2.20.1 snapshot yet, but in 2.20.0 the problem seem to be, that the initialization of the "EnvironmentPropertySource" class is missing.

Workaround:
For eclipse based application you can delete the folder "\configuration\org.eclipse.osgi" before starting the application.
In this case the folder is created from scratch and the log file + content is created.

If the folder already exists, the log messages do not appear.
There seems to be a problem with the order of the plugins, so log4j is loaded too early or at a wrong time.

[MLausberg]

I have also tested the versions 2.17.3 and 2.19.1 and get the same problem.
Only if the folder "\configuration\org.eclipse.osgi" does not exist yet the logging works.

If there are ideas for further analysis I am open for any suggestion

[ppkarwasz]

@MLausberg,

Do you have a minimal Eclipse RCP application reproducing the problem you can share? It would greatly speedup debugging the issue.

[MLausberg]

When logging is working a class Breakpoint on "EnvironmentPropertySource" lead to this stack trace and when logging does not work the breakpoint is not hit.

Daemon Thread [Start Level: Equinox Container: 3abe5d12-1e59-42c3-aab9-20b2d289b59e] (Class load: EnvironmentPropertySource)	
	owns: Object  (id=54)	
	Class<T>.getDeclaredConstructors0(boolean) line: not available [native method]	
	Class<T>.privateGetDeclaredConstructors(boolean) line: not available	
	Class<T>.getConstructor0(Class<?>[], int) line: not available	
	Class<T>.getConstructor(Class<?>...) line: not available	
	ServiceLoader$1.run() line: not available	
	ServiceLoader$1.run() line: not available	
	AccessController.executePrivileged(PrivilegedExceptionAction<T>, AccessControlContext, Class<?>) line: not available	
	AccessController.doPrivileged(PrivilegedExceptionAction<T>) line: not available	
	ServiceLoader<S>.getConstructor(Class<?>) line: not available	
	ServiceLoader$LazyClassPathLookupIterator<T>.hasNextService() line: not available	
	ServiceLoader$LazyClassPathLookupIterator<T>.hasNext() line: not available	
	ServiceLoader$2.hasNext() line: not available	
	ServiceLoader$3.hasNext() line: not available	
	ServiceLoaderUtil$ServiceLoaderSpliterator<S>.tryAdvance(Consumer<? super S>) line: 156	
	ServiceLoaderUtil$ServiceLoaderSpliterator<S>(Spliterator<T>).forEachRemaining(Consumer<? super T>) line: not available	
	Streams$ConcatSpliterator$OfRef<T>(Streams$ConcatSpliterator<T,T_SPLITR>).forEachRemaining(Consumer<? super T>) line: not available	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).copyInto(Sink<P_IN>, Spliterator<P_IN>) line: not available	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).wrapAndCopyInto(S, Spliterator<P_IN>) line: not available	
	ForEachOps$ForEachOp$OfRef<T>(ForEachOps$ForEachOp<T>).evaluateSequential(PipelineHelper<T>, Spliterator<S>) line: not available	
	ForEachOps$ForEachOp$OfRef<T>.evaluateSequential(PipelineHelper, Spliterator) line: not available	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).evaluate(TerminalOp<E_OUT,R>) line: not available	
	ReferencePipeline$2(ReferencePipeline<P_IN,P_OUT>).forEach(Consumer<? super P_OUT>) line: not available	
	PropertiesUtil$Environment.<init>(PropertySource) line: 467	
	PropertiesUtil$Environment.<init>(PropertySource, PropertiesUtil$1) line: 444	
	PropertiesUtil.<init>(PropertySource) line: 88	
	PropertiesUtil.<init>(String, boolean) line: 80	
	PropertiesUtil.<clinit>() line: 56	
	Constants.<clinit>() line: 30	
	AbstractLogger.createClassForProperty(String, Class<ReusableMessageFactory>, Class<ParameterizedMessageFactory>) line: 203	
	AbstractLogger.<clinit>() line: 92	
	Activator.<clinit>() line: 51	
	NativeConstructorAccessorImpl.newInstance0(Constructor<?>, Object[]) line: not available [native method]	
	NativeConstructorAccessorImpl.newInstance(Object[]) line: not available	
	DelegatingConstructorAccessorImpl.newInstance(Object[]) line: not available	
	Constructor<T>.newInstanceWithCaller(Object[], boolean, Class<?>) line: not available	
	Constructor<T>.newInstance(Object...) line: not available	
	BundleContextImpl.loadBundleActivator() line: 801	
	BundleContextImpl.start() line: 753	
	EquinoxBundle.startWorker0() line: 1032	
	EquinoxBundle$EquinoxModule.startWorker() line: 371	
	EquinoxBundle$EquinoxModule(Module).doStart(Module$StartOptions...) line: 605	
	EquinoxBundle$EquinoxModule(Module).start(Module$StartOptions...) line: 468	
	ModuleContainer$ContainerStartLevel$2.run() line: 1852	
	EquinoxContainerAdaptor$1$1.execute(Runnable) line: 136	
	ModuleContainer$ContainerStartLevel.incStartLevel(int, List<Module>, boolean) line: 1845	
	ModuleContainer$ContainerStartLevel.incStartLevel(int, List<Module>, List<Module>, List<Module>, List<Module>) line: 1788	
	ModuleContainer$ContainerStartLevel.doContainerStartLevel(Module, int, FrameworkListener...) line: 1750	
	ModuleContainer$ContainerStartLevel.dispatchEvent(Module, FrameworkListener[], int, Integer) line: 1672	
	ModuleContainer$ContainerStartLevel.dispatchEvent(Object, Object, int, Object) line: 1	
	EventManager.dispatchEvent(Set<Entry<K,V>>, EventDispatcher<K,V,E>, int, E) line: 234	
	EventManager$EventThread<K,V,E>.run() line: 345	

[HannesWell]

@MLausberg I assume that this is a configuration error of your Eclipse product.
Can you share your product configuration? The most important things is probably to auto-start the org.apache.aries.spifly.dynamic.bundle at level 2. That is the implementation of the OSGi Service Loader Mediator Specification currently used in Eclipse. It ensures that the Java ServiceLoader finds the provided services of other bundles even if the consuming bundle does not depend on the providing bundle (which usually means that the consumer could not know/access the provider).
One example is
https://github.com/eclipse-packaging/packages/blob/01bc0c0b9d5c79efeb76bed2193a41bdf383c576/packages/org.eclipse.epp.package.java.product/epp.product#L63

But then it is still surprising that logging works at the first time you start your application.

[ppkarwasz]

Theoretically the Log4j API (unlike SLF4J 2.x) and its implementations can find each other in an OSGi environment without a Service Loader Mediator.

Since I never developed OSGi applications, I don't know how common Apache Aries SPI Fly is in modern OSGi apps. If it is a de facto standard, we can remove a lot of custom code and just rely on it.

Anyway Log4j's behavior does not provide any advanced OSGi features: the Log4j API binds with a single implementation when the bundle is started and changing or upgrading the backend at runtime is impossible.

[MLausberg]

The "config.ini" looks like

#This configuration file was written by: org.eclipse.equinox.internal.frameworkadmin.equinox.EquinoxFwConfigFileParser
#Tue Sep 19 07:48:14 CEST 2023
eclipse.product=de.dsa.mancats3.product
osgi.splashPath=platform\:/base/plugins/de.dsa.mancats3
org.eclipse.equinox.simpleconfigurator.configUrl=file\:org.eclipse.equinox.simpleconfigurator/bundles.info
osgi.bundles.defaultStartLevel=4
eclipse.application=de.dsa.rts.richgui.framework.RtsApp
osgi.bundles=reference\:file\:org.eclipse.equinox.simpleconfigurator_1.4.200.v20221111-1340.jar@1\:start
eclipse.p2.data.area=@config.dir/../p2/
eclipse.p2.profile=DefaultProfile
osgi.framework=file\:plugins/org.eclipse.osgi_3.18.400.v20230509-2241.jar
osgi.framework.extensions=reference\:file\:org.eclipse.osgi.compatibility.state_1.2.800.v20221116-1440.jar

And the product contains

   <configurations>
      <plugin id="org.apache.aries.spifly.dynamic.bundle" autoStart="true" startLevel="2" />
      <plugin id="org.apache.felix.scr" autoStart="true" startLevel="2" />
      <plugin id="org.apache.logging.log4j.api" autoStart="true" startLevel="2" />
      <plugin id="org.apache.logging.log4j.core" autoStart="true" startLevel="2" />
      <plugin id="org.eclipse.core.runtime" autoStart="true" startLevel="0" />
      <plugin id="org.eclipse.equinox.app" autoStart="true" startLevel="2" />
      <plugin id="org.eclipse.equinox.common" autoStart="true" startLevel="2" />
      <plugin id="org.eclipse.equinox.event" autoStart="true" startLevel="2" />
      <plugin id="org.eclipse.equinox.p2.reconciler.dropins" autoStart="true" startLevel="0" />
      <plugin id="org.eclipse.equinox.simpleconfigurator" autoStart="true" startLevel="1" />
   </configurations>

I adapted the line as proposed, but still no success
org.apache.aries.spifly.dynamic.bundle,1.3.6,plugins/org.apache.aries.spifly.dynamic.bundle_1.3.6.jar,2,true