Skip to content

Conversation

johnmay
Copy link
Member

@johnmay johnmay commented Aug 23, 2022

As per #873 depending on log4j-core causes issues. By removing some functionality e.g. runtime level set we don't need to depend on log4j-core and should make things work better overall.

WIP - need to do some testing on this in a down stream library

… package private so users don't create it in their own code (it should be via the factory). We also remove the compile time dependency on log4j-core, a use should include this them selves and may wish to use something like log4j-to-slf4j.
…me module so we can initialize it directly and don't need to use reflection.
…e explictly. We can switch on a system property in the XML now which I've done.
…bly throw an exception and is better controlled with Log Config
@johnmay johnmay marked this pull request as draft August 23, 2022 08:43
@egonw egonw self-requested a review August 23, 2022 08:58
@uli-f uli-f mentioned this pull request Aug 23, 2022
@johnmay
Copy link
Member Author

johnmay commented Aug 23, 2022

Not sure what is wrong with sonarcloud not finding the plugin

@egonw
Copy link
Member

egonw commented Aug 23, 2022

Not sure what is wrong with sonarcloud not finding the plugin

seems to be a glitch on their side

@egonw
Copy link
Member

egonw commented Aug 23, 2022

Maybe has to do with the update a few days ago? https://twitter.com/SonarQube/status/1560248339861577730

@johnmay
Copy link
Member Author

johnmay commented Aug 23, 2022

Reran and all fine, I will do some testing when I have to check it works correctly but if you have a look at changes you'll see the gist is to guard against errors @uli-f had.

Copy link
Member

@egonw egonw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like what you're doing here. Thanks!

@egonw
Copy link
Member

egonw commented Aug 25, 2022

@johnmay, you merge it when you're done with your extra testing, right?

@johnmay
Copy link
Member Author

johnmay commented Aug 25, 2022

Yep I’ll try and do that today

@johnmay
Copy link
Member Author

johnmay commented Aug 25, 2022

Right testing things and sort of works but @egonw/@uli-f do we think it makes sense to provide a default logging config?

Testing a simple Main like this:

public class Main {
    public static void main(String[] args) throws InvalidSmilesException {
        SmilesParser smipar = new SmilesParser(SilentChemObjectBuilder.getInstance());
        IAtomContainer mol = smipar.parseSmiles("CCO");
        ILoggingTool loggingTool = LoggingToolFactory.createLoggingTool(Main.class);
        loggingTool.warn("This is a warning!");
        loggingTool.debug("This is a debug mesg!");
    }
}

By default you get STDERR messages...

org.openscience.cdk.depict.Main WARN: This is a warning!

And following 391434c setting -Dcdk.debugging=true will also give you the debug mesg (and some in the builder).

...
org.openscience.cdk.DynamicFactory DEBUG: registered 'IMapping' with 'Mapping' implementation
org.openscience.cdk.DynamicFactory DEBUG: registered 'IChemObject' with 'ChemObject' implementation
org.openscience.cdk.depict.Main WARN: This is a warning!
org.openscience.cdk.depict.Main DEBUG: This is a debug mesg!

Now if I include cdk-log4j i get a warning from Log4J there is no implementation (i.e. you need log4j-core:

ERROR StatusLogger Log4j2 could not find a logging implementation. Please add log4j-core to the classpath. Using SimpleLogger to log to the console...

So include log4j-core and it's happy, well sort of you need to set the config file as follows:

-Dcdk.debugging=true -Dlog4j2.configurationFile=org/openscience/cdk/tools/cdk-log4j2.xml

The other option is we move it to "log4j2.xml" and it will be picked up by default. But as @uli-f normally you want the downstream application to set it's logging.

My thoughts are we move org/openscience/cdk/tools/cdk-log4j2.xml to cdk-log4j2.xml so it's a bit quicker to type and add some doc to the Log4jLogger class.

Any other suggestions?

@johnmay
Copy link
Member Author

johnmay commented Aug 25, 2022

To add.. if you don't specify the configuration Log4J default to Error.

@uli-f
Copy link
Member

uli-f commented Aug 26, 2022

@johnmay Thank you so much for implementing those changes and summarizing your tests in the comment above.

Best news first: The ClassCastException does not happen anymore if both the module cdk-log4j and the dependency log4j-to-slf4j are on the classpath 😃

However, with the following dependencies

<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-core</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-atomtype</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-interfaces</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-silent</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-smiles</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>org.openscience.cdk</groupId>
  <artifactId>cdk-log4j</artifactId>
  <version>2.8-SNAPSHOT</version>
</dependency>

in my (or better John's) downstream application Main

public class Main {
    public static void main(String[] args) throws InvalidSmilesException {
        SmilesParser smipar = new SmilesParser(SilentChemObjectBuilder.getInstance());
        IAtomContainer mol = smipar.parseSmiles("CCO");
        ILoggingTool loggingTool = LoggingToolFactory.createLoggingTool(Main.class);
        loggingTool.warn("This is a warning!");
        loggingTool.debug("This is a debug mesg!");
    }
}

I get the following stacktrace:

ERROR StatusLogger Unable to create Lookup for ctx
 java.lang.NoSuchMethodError: 'java.lang.ClassLoader[] org.apache.logging.log4j.util.LoaderUtil.getClassLoaders()'
	at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.getServiceProviders(ThreadContextDataInjector.java:77)
	at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.<clinit>(ThreadContextDataInjector.java:64)
	at org.apache.logging.log4j.core.impl.ThreadContextDataInjector$ForCopyOnWriteThreadContextMap.<init>(ThreadContextDataInjector.java:220)
	at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createDefaultInjector(ContextDataInjectorFactory.java:94)
	at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:71)
	at org.apache.logging.log4j.core.lookup.ContextMapLookup.<init>(ContextMapLookup.java:34)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
	at org.apache.logging.log4j.core.util.ReflectionUtil.instantiate(ReflectionUtil.java:189)
	at org.apache.logging.log4j.core.lookup.Interpolator.<init>(Interpolator.java:81)
	at org.apache.logging.log4j.core.lookup.Interpolator.<init>(Interpolator.java:100)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.<init>(AbstractConfiguration.java:133)
	at org.apache.logging.log4j.core.config.NullConfiguration.<init>(NullConfiguration.java:32)
	at org.apache.logging.log4j.core.LoggerContext.<clinit>(LoggerContext.java:74)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.createContext(ClassLoaderContextSelector.java:254)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:218)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:136)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:123)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:117)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:150)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:599)
	at org.openscience.cdk.tools.Log4jLoggingTool.<init>(Log4jLoggingTool.java:147)
	at org.openscience.cdk.tools.Log4jLoggingTool.create(Log4jLoggingTool.java:396)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.openscience.cdk.tools.LoggingToolFactory.instantiateWithCreateMethod(LoggingToolFactory.java:107)
	at org.openscience.cdk.tools.LoggingToolFactory.initializeLoggingTool(LoggingToolFactory.java:93)
	at org.openscience.cdk.tools.LoggingToolFactory.createLoggingTool(LoggingToolFactory.java:81)
	at org.openscience.cdk.DynamicFactory.<clinit>(DynamicFactory.java:133)
	at org.openscience.cdk.silent.SilentChemObjectBuilder$Holder.<init>(SilentChemObjectBuilder.java:121)
	at org.openscience.cdk.silent.SilentChemObjectBuilder$Holder.<clinit>(SilentChemObjectBuilder.java:119)
	at org.openscience.cdk.silent.SilentChemObjectBuilder.getInstance(SilentChemObjectBuilder.java:257)
	at ai.pending.Main.main(Main.java:14)
Exception in thread "main" java.lang.ExceptionInInitializerError
	at org.openscience.cdk.silent.SilentChemObjectBuilder$Holder.<init>(SilentChemObjectBuilder.java:121)
	at org.openscience.cdk.silent.SilentChemObjectBuilder$Holder.<clinit>(SilentChemObjectBuilder.java:119)
	at org.openscience.cdk.silent.SilentChemObjectBuilder.getInstance(SilentChemObjectBuilder.java:257)
	at ai.pending.Main.main(Main.java:14)
Caused by: java.lang.RuntimeException: Could not create custom logging class
	at org.openscience.cdk.tools.LoggingToolFactory.instantiateWithCreateMethod(LoggingToolFactory.java:114)
	at org.openscience.cdk.tools.LoggingToolFactory.initializeLoggingTool(LoggingToolFactory.java:93)
	at org.openscience.cdk.tools.LoggingToolFactory.createLoggingTool(LoggingToolFactory.java:81)
	at org.openscience.cdk.DynamicFactory.<clinit>(DynamicFactory.java:133)
	... 4 more
Caused by: java.lang.reflect.InvocationTargetException
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.openscience.cdk.tools.LoggingToolFactory.instantiateWithCreateMethod(LoggingToolFactory.java:107)
	... 7 more
Caused by: java.lang.NoClassDefFoundError: Could not initialize class org.apache.logging.log4j.core.impl.ThreadContextDataInjector
	at org.apache.logging.log4j.core.impl.ThreadContextDataInjector$ForCopyOnWriteThreadContextMap.<init>(ThreadContextDataInjector.java:220)
	at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createDefaultInjector(ContextDataInjectorFactory.java:94)
	at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:71)
	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.<init>(ReusableLogEventFactory.java:42)
	at org.apache.logging.log4j.core.config.LoggerConfig.<clinit>(LoggerConfig.java:101)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.<init>(AbstractConfiguration.java:136)
	at org.apache.logging.log4j.core.config.NullConfiguration.<init>(NullConfiguration.java:32)
	at org.apache.logging.log4j.core.LoggerContext.<clinit>(LoggerContext.java:74)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.createContext(ClassLoaderContextSelector.java:254)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:218)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:136)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:123)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:117)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:150)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:599)
	at org.openscience.cdk.tools.Log4jLoggingTool.<init>(Log4jLoggingTool.java:147)
	at org.openscience.cdk.tools.Log4jLoggingTool.create(Log4jLoggingTool.java:396)
	... 12 more

My understanding is that we all agree that logging with all its APIs and libs is anything but easy to manage.

By introducing another logging framework (ILoggingTool, LoggingFactory, Log4JLoggingTool) in CDK this makes things - from my perspective - just more complicated.

I'd opt for simplifying things by doing what most other libraries do:

  • Just use one of the APIs for logging (preferably slf4j-api, as this seem the de-facto standard at the moment).
  • Anything else happens in the downstream application.
  • This would require the module cdk-log4j and anything else that relates to the CDK logging to be removed (ILoggingTool, LoggingFactory, Log4JLoggingTool, any logging config such as the cdk-log4j2.xml).

A few more comments:

The other option is we move it to "log4j2.xml" and it will be picked up by default. But as @uli-f normally you want the downstream application to set it's logging.

  • I would prefer to not move the logging config to log4j2.xml so that it is not picked up automatically.
  • Even the System Property cdk.debug seems a bit out of place to me. The downstream application can just add a logging implementation and configures logging by means of the chosen logging implementation.
  • Having the logging go to stderr by default also does not seem great to me. This forces the downstream application to actually take care of logging; otherwise your console gets (ab)used for logging messages.

@johnmay
Copy link
Member Author

johnmay commented Aug 26, 2022

I had suggested this to Egon before but now I think I do like we have our even simpler API that doesn’t depend on anything. We don’t really use logging much anyways so the stderr isn’t much of an issue :). @dan2097 has noted before that the log4j2 api part has more downstream usages than slf4j. Also I believe log4j1, slf4j and logback are all the same author, and feels like rewarding bad behaviour.

How are you running your application, I think your errors could be you have misspackaged it, property files may have gone missing. Also if you are using slf4j there is no need to include cdk-log4j/log4j-to-slf4j at all and instead just write your own wrapper that goes to slf4j?

@uli-f
Copy link
Member

uli-f commented Aug 26, 2022

I had suggested this to Egon before but now I think I do like we have our even simpler API that doesn’t depend on anything.

Okay. If that is what you agreed on, I am happy to come on board with the decision if it does not cause issues with any logging dependencies.

@dan2097 has noted before that the log4j2 api part has more downstream usages than slf4j.

Good to know! I am not opinionated here as long as the logging is primarily done against a logging API and does not require a logging implementation.

How are you running your application, I think your errors could be you have misspackaged it, property files may have gone missing.

Using IntelliJ which does a lot automagically, but is usually pretty good with maven builds. Checked out your branch, compiled, and installed in local repo. Then set up another maven project the the following pom.xml:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>ai.pending</groupId>
    <artifactId>cdk-lib-test</artifactId>
    <name>CDK Library Test</name>
    <version>1.0-SNAPSHOT</version>
    <dependencies>
        <dependency>
            <groupId>org.openscience.cdk</groupId>
            <artifactId>cdk-core</artifactId>
            <version>2.8-SNAPSHOT</version>
        </dependency>
        <dependency>
            <groupId>org.openscience.cdk</groupId>
            <artifactId>cdk-atomtype</artifactId>
            <version>2.8-SNAPSHOT</version>
        </dependency>
        <dependency>
            <groupId>org.openscience.cdk</groupId>
            <artifactId>cdk-interfaces</artifactId>
            <version>2.8-SNAPSHOT</version>
        </dependency>
        <dependency>
            <groupId>org.openscience.cdk</groupId>
            <artifactId>cdk-silent</artifactId>
            <version>2.8-SNAPSHOT</version>
        </dependency>
        <dependency>
            <groupId>org.openscience.cdk</groupId>
            <artifactId>cdk-smiles</artifactId>
            <version>2.8-SNAPSHOT</version>
        </dependency>
        <dependency>
          <groupId>org.openscience.cdk</groupId>
          <artifactId>cdk-log4j</artifactId>
          <version>2.8-SNAPSHOT</version>
        </dependency>
    </dependencies>
    <properties>
        <argLine></argLine>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    </properties>
    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-compiler-plugin</artifactId>
                <version>3.8.1</version>
                <configuration>
                    <source>17</source>
                    <target>17</target>
                </configuration>
            </plugin>
        </plugins>
    </build>
</project>

And run your Main program.

And now it does not crash anymore!
IntelliJ sometimes has an issue with caching, so I actually reloaded the maven project in between all my library swapping-in-and-out, but obviously wasn't good enough.
All good now, no stacktrace anymore 👍🏼

Also if you are using slf4j there is no need to include cdk-log4j/log4j-to-slf4j at all and instead just write your own wrapper that goes to slf4j?

That is a good point and definitely something I might consider adding to the logging framework.

@johnmay Would you prefer to have this added now or once the branch is merged?

@dan2097
Copy link

dan2097 commented Aug 26, 2022

@dan2097 has noted before that the log4j2 api part has more downstream usages than slf4j.

I think the conclusion was actually the opposite https://mvnrepository.com/artifact/org.slf4j/slf4j-api vs https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-api, but the other points still stand. [admitedly usage stats can be a bit misleading as legacy frameworks like log4j v1 and commons logging still rank very highly]
https://www.slf4j.org/faq.html#changesInVersion200 sounds like it'll keep things "interesting".

@uli-f
Copy link
Member

uli-f commented Aug 26, 2022

https://www.slf4j.org/faq.html#changesInVersion200 sounds like it'll keep things "interesting"

That actually sounds good to me.
Relying on the Java model of services and providers instead of ClassLoader mechanism might be a good thing... 🤷🏼

@dan2097
Copy link

dan2097 commented Aug 26, 2022

https://www.slf4j.org/faq.html#changesInVersion200 sounds like it'll keep things "interesting"

That actually sounds good to me. Relying on the Java model of services and providers instead of ClassLoader mechanism might be a good thing... 🤷🏼

I meant more that the v1.7 API doesn't appear to be able to bind to v2.0 implementations and vice versa, which sounds like itwould neccesitate exclusion of v1.7 artifacts if only some libraries have moved to v2.0

@johnmay
Copy link
Member Author

johnmay commented Aug 26, 2022

JWM Todo: may need to either add log4j-core to test or remove the cdk-log4j dependency.

@sonarqubecloud
Copy link

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 27 Code Smells

42.5% 42.5% Coverage
32.8% 32.8% Duplication

@johnmay johnmay marked this pull request as ready for review September 10, 2022 06:59
@johnmay johnmay merged commit bca17b1 into master Sep 10, 2022
@johnmay johnmay deleted the cdk-log4j-improvements branch October 20, 2024 14:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants