Enhancement - Internal Logging Facade

[dogourd]

Related discussions that already exist: #829

Added internal logging facade to provide user optionality for using logging implementation.
In some special scenarios (javaagent + jboss), when using guava in javaagent, some APIs of guava will cause j.u.l.LogManager to be initialized prematurely, and eventually cause jboss to fail to start.
Consider adding a log facade to support users to choose what they want The desired log implementation.

related discussion: Failed initializing module org.jboss.as.logging

[cpovirk]

Thanks for the report and for digging up the links.

The downsides in #829 would still be concerns, but maybe there are other things we could do to help.

• Is there a way for us to detect whether logging is ready? (Even if it involves reflectively looking up a JBoss API, we might be able to do it.)
• Maybe we could provide a system property that could be used to disable logging entirely (or to write directly to System.err instead of to java.util.logging)? (Such a feature could also be useful for "SEVERE: input future failed" spams stdout/stderr #2134.)
• Other ideas?

[ben-manes]

The platform logger would be ideal, where you could use System.Logger and it routes to the proper backend (where jul is the default). Unfortunately that was introduced in Java 9 and Android chose to not support it and break SE compatibility instead (I do not know why).

[cpovirk]

Huh, thanks, I'd totally forgotten about that. @dogourd, any idea whether that would solve your particular problem with Guava+JBoss?

(Even if not, it's something for us to consider for general configurability, especially building on what I hope will be the success of conditionally using our first Java 9+ API in Guava, as we were discussing last week.)

[dogourd]

Actually, it doesn't work. The reason for the failure to start JBoss is that we manipulated j.u.l.LogManager before JBoss. In Java, this should only happen during the premain execution phase of a javaagent. However, a javaagent does not have the authority to choose the Java version; it is determined by the target application.

I think adding a switch is a viable solution, but personally, I'm not fond of using System property to control it. Its scope is too broad as both the javaagent and the application may rely on Guava but be loaded by isolated class loaders. Moreover, we only want to control the logging behavior of Guava components within the javaagent, whereas the System property approach would affect all Guava instances under different class loaders.

[ben-manes]

System.Logger resolves using jdk.internal.logger.LazyLoggers, which is bootstrap aware. Since Guava only logs in exceptional conditions, initializing the logger but not using it should be fine. Following that logic, a memoizing supplier for the loggers would have the same effect, so using the cost of invoking through the supplier would be minimal while deferring the initialization of the logger until the first need. Then the if the java agent is not forcing a log message it would be compatible. This is basically what LazyLoggerAccessor does as an adapter to defer initialization if created during VM boot.

static final Supplier<Logger> logger = Suppliers.memoize(() -> Logger.getLogger(Xyz.class.getName()));
logger.get().log(Level.WARNING, msg);

[dogourd]

@ben-manes Yeah, based on the scenarios I've encountered so far (where CacheBuilder and com.google.common.base.Platform classes are loaded), it should do the trick. However, it does introduce some randomness because it doesn't explicitly control the initialization behavior; it depends on the runtime execution conditions.

[cpovirk]

Ah, interesting.

The logger in Platform has been unused for a while, but I've never had enough motivation to rip it out. I'm now testing a change to do that.

I should be able to change the CacheBuilder logger to be lazily loaded, too.

I might worry a little about doing that for all our loggers, if only because of the extra classes it would require, which would be unfortunate for our Android users. But we could make the change only in guava-jre (at the cost of a small diff vs. guava-android), or we could reduce the cost by declaring a single class in each package that contains all the loggers for the package. But it should be fine to try out with one class, especially one that already contains a large number of supporting classes.

If you comment out the loggers (and their usages) in those two classes, does everything work? I could try to deal with all the loggers now, but I'm trying to take care of a few different Guava things at once, so it's nice if I know where I can take the quick and dirty approach :)

[ben-manes]

For this use-case, how worthwhile is it for guava to support it? I would think that an agent should have minimal dependencies to avoid surprises. If you only need the cache then you could try caffeine, which uses the platform logger. Another option is to shade and strip out the logging by bytecode rewriting.

[cpovirk]

Thanks, those are both things I intended to say but forgot :( Definitely use Caffeine if you can. And, as I'll be pointing out in the release notes, we don't test Guava usage from a Java agent (as you can tell from the crashes... :)), so I don't know how likely it is to continue working. It's easy enough for us to work around the specific problem we've been discussing here, but you might encounter problems in the future, and if things get hard to fix, we might give up.

[dogourd]

or we could reduce the cost by declaring a single class in each package that contains all the loggers for the package

To put it further, can I think of this class as a LoggerFactory? Can we read the configuration from the current classloader or the thread context classloader here to control Guava's logging behavior?

If you comment out the loggers (and their usages) in those two classes, does everything work?

Yes, based on my current situation, removing these two loggers can solve the problem.

It's easy enough for us to work around the specific problem we've been discussing here, but you might encounter problems in the future

Yes, actually I lean more towards this being a JBoss issue. Any component within the Javaagent that is capable of bridging to jul could potentially conflict with it. However, the JBoss team believes they have mentioned in the error message that this is related to j.u.l.LogManager so it is an expected outcome.

While debugging the initialization process of j.u.l.LogManager, I found that in my case, not only Guava but also apache httpclient initializes it. However, the fortunate thing is that apache httpclient has a logging facade called commons-logging, which allows me to completely bypass the initialization of jul through some configuration. But so far, I haven't found a straightforward way to achieve this in Guava. My options are either to give up some APIs or build a downstream branch to handle this.

I would think that an agent should have minimal dependencies to avoid surprises.

I completely understand your point, and I agree. Guava indeed provides many excellent and practical features, such as base, hash, io, collect, cache, and more. Honestly, I really don't want to give it up either.

BTW, in the discussion so far, there have been multiple mentions of using Caffeine as a cache implementation. However, for this particular issue, it's not feasible. Caffeine 3.x requires JDK 11, which is not an acceptable requirement when developing a Javaagent. Javaagents are always expected to be compatible with older Java versions. As for Caffeine 2.x, although I haven't tried it yet, I anticipate running into the same issue since it also directly relies on jul according to the related API documentation.

Regarding whether it's worth it for Guava to address this problem, I have my doubts as well. I have another solution in mind where I can make my Javaagent run in a separate thread with a delayed start, ensuring that it initializes after JBoss startup. It would appear like an Attach operation. This is currently the least invasive solution, although it may sacrifice some functionality of the Javaagent due to the limitations imposed by the JVM on retransformClass.

[ben-manes]

@dogourd have you considered shading the dependency and using a rule to remove the logger during the byte code transform?

[dogourd]

@ben-manes I'm afraid I don't want to go that route. I'd rather ditch some of the Guava APIs before the bytecode transformation is completed.

[cpovirk]

(I have changes to address both loggers out for review.)

To put it further, can I think of this class as a LoggerFactory? Can we read the configuration from the current classloader or the thread context classloader here to control Guava's logging behavior?

While I wouldn't present it as a configurable factory, I would say that we might be able to put in some kind of conditional along the lines of "if (!inPremain()) { log(...); }." Is that something we can detect from the classloader that loads LoggerFactory or from the context class loader? I think that's what you were suggesting? I could believe that the context class loader would be better, since it might change over time(??), in which case we might be able to log later in the process's lifetime?

[dogourd]

Is that something we can detect from the classloader that loads LoggerFactory or from the context class loader?

If you don't wanna use ClassLoader.getResource, I think you might need to maintain a weak-referenced map for classLoader, something like this:

WeakMap<ClassLoader, Map<String, String>> clProperties;
String getProperty(String key) {
    Map<String, String> properties = clProperties.get(Thread.currentThread().getContextClassLoader());
    if (properties != null) {
        return properties.get(key);
    }
    return System.getProperty(key);
}

void setProperty(String key, String value) {
    ClassLoader cl = Thread.currentThread().getContextClassLoader();
    Map<String, String> properties = clProperties.get();
    if (properties == null) {
        properties = new HashMap<>();
        clProperties.put(cl, properties);
    }
    properties.put(key, value);
}

I've come across similar code in some libraries before, but, um, it's hard for me to say whether it's good or bad, you know.

[cpovirk]

The changes to remove/delay the loggers landed in 32.1.0, but because we got the Gradle metadata wrong in that release, I suggest going straight to 32.1.1, which also contains the fix for that problem.