Skip to content

Enhancement - Internal Logging Facade #6566

New issue
New issue
Closed
Closed
Enhancement - Internal Logging Facade#6566
Labels
P3no SLOpackage=generaltype=enhancementMake an existing feature better
@dogourd

Description

@dogourd
dogourd
opened on Jun 20, 2023

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

Activity

cpovirk

cpovirk commented on Jun 20, 2023

@cpovirk
cpovirk
on Jun 20, 2023
Member

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?
cpovirk
added
type=enhancementMake an existing feature better
package=general
on Jun 20, 2023
ben-manes

ben-manes commented on Jun 20, 2023

@ben-manes
ben-manes
on Jun 20, 2023
Contributor

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

cpovirk commented on Jun 20, 2023

@cpovirk
cpovirk
on Jun 20, 2023
Member

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

dogourd commented on Jun 21, 2023

@dogourd
dogourd
on Jun 21, 2023
Author

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

ben-manes commented on Jun 21, 2023

@ben-manes
ben-manes
on Jun 21, 2023
Contributor

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

dogourd commented on Jun 21, 2023

@dogourd
dogourd
on Jun 21, 2023
Author

@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

cpovirk commented on Jun 21, 2023

@cpovirk
cpovirk
on Jun 21, 2023
Member

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

ben-manes commented on Jun 21, 2023

@ben-manes
ben-manes
on Jun 21, 2023 · edited by ben-manes
Contributor

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

cpovirk commented on Jun 21, 2023

@cpovirk
cpovirk
on Jun 21, 2023
Member

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

dogourd commented on Jun 22, 2023

@dogourd
dogourd
on Jun 22, 2023
Author

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

ben-manes commented on Jun 22, 2023

@ben-manes
ben-manes
on Jun 22, 2023
Contributor

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

dogourd

dogourd commented on Jun 23, 2023

@dogourd
dogourd
on Jun 23, 2023
Author

@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.

copybara-service
mentioned this on Jun 23, 2023
copybara-service
added a commit that references this issue on Jun 23, 2023

Delay initializing the `CacheBuilder` logger until it is needed.

0bd3193
cpovirk

cpovirk commented on Jun 23, 2023

@cpovirk
cpovirk
on Jun 23, 2023 · edited by cpovirk
Member

(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?

copybara-service
added a commit that references this issue on Jun 23, 2023

Delay initializing the `CacheBuilder` logger until it is needed.

de62703
cpovirk
added
P3no SLO
on Jun 23, 2023
dogourd

dogourd commented on Jun 25, 2023

@dogourd
dogourd
on Jun 25, 2023
Author

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.

copybara-service
mentioned this on Jun 26, 2023
copybara-service
added 2 commits that reference this issue on Jun 26, 2023

Remove obsolete GWT-RPC logging code.

3e210f3

Remove obsolete GWT-RPC logging code.

e42d4e8
cpovirk

cpovirk commented on Jun 30, 2023

@cpovirk
cpovirk
on Jun 30, 2023 · edited by cpovirk
Member

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.

dogourd
closed this as completedon Jul 3, 2023
cpovirk
mentioned this on Aug 3, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    P3no SLOpackage=generaltype=enhancementMake an existing feature better

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

      Development

      No branches or pull requests

        Participants

        @ben-manes@cpovirk@dogourd

        Issue actions
          Enhancement - Internal Logging Facade · Issue #6566 · google/guava