8343449: Nashorn method handle debug logging breaks with log4j-jul

[ppkarwasz]

The MethodHandleFactory and especially its FUNC static field are heavily used during the static initialization process.

To prevent nullability problems in the static MethodHandleFactory fields, StandardMethodHandleFunctionality relies on DebugLogger.DISABLED_LOGGER.isEnabled() being false during the initialization process.
If this assumption is true, static MethodHandleFactory fields will not be accessed by StandardMethodHandleFunctionality.
If this assumption, however, fails (as described in apache/logging-log4j2#3119) the static initialization fails with some unforeseen NPEs.

We improve the above machanism by:

• Replacing the StandardMethodHandleFunctionality.log field with a static field in the top level class.
• The new log field is placed last, so it holds the value null until the end of static initialization.
• All the usages of the log fields are checked to ensure that they contain a null-check.

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace

Issue

• JDK-8343449: Nashorn method handle debug logging breaks with log4j-jul (Bug - P4)

Reviewers

• Attila Szegedi (@szegedi - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/nashorn.git pull/19/head:pull/19
$ git checkout pull/19

Update a local copy of the PR:
$ git checkout pull/19
$ git pull https://git.openjdk.org/nashorn.git pull/19/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 19

View PR using the GUI difftool:
$ git pr show -t 19

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/nashorn/pull/19.diff

[bridgekeeper]

Hi @ppkarwasz, welcome to this OpenJDK project and thanks for contributing!

We do not recognize you as Contributor and need to ensure you have signed the Oracle Contributor Agreement (OCA). If you have not signed the OCA, please follow the instructions. Please fill in your GitHub username in the "Username" field of the application. Once you have signed the OCA, please let us know by writing /signed in a comment in this pull request.

If you already are an OpenJDK Author, Committer or Reviewer, please click here to open a new issue so that we can record that fact. Please use "Add GitHub user ppkarwasz" as summary for the issue.

If you are contributing this work on behalf of your employer and your employer has signed the OCA, please let us know by writing /covered in a comment in this pull request.

[openjdk]

@ppkarwasz This change now passes all automated pre-integration checks.

After integration, the commit message for the final commit will be:

8343449: Nashorn method handle debug logging breaks with log4j-jul

Reviewed-by: attila

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been no new commits pushed to the main branch. If another commit should be pushed before you perform the /integrate command, your PR will be automatically rebased. If you prefer to avoid any potential automatic rebasing, please check the documentation for the /integrate command for further details.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@szegedi) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

[szegedi]

Okay, I dug into this a bit more and also in the analysis in apache/logging-log4j2#3119. Why would DebugLogger.DISABLED_LOGGER.isEnabled() return true when used with log4j-jul? DISABLED_LOGGER is created with Level.OFF, so it's always disabled (as far as DebugLogger.isEnabled is concerned - it's a final field set by DebugLogger ctor if the level is OFF.)

OTOH, it's possible that maybe logger.isLoggable(level) check on MethodHandleFactory.java:281 might return true now? In the stack trace in apache/logging-log4j2#3119 it is invoked from MethodHandleFactory.java:376 which passed Level.INFO, so is it the case that a logger created with Level.OFF returned true from isLoggable(Level.INFO) call? Is that expected behavior in log4j-jul?

[ppkarwasz]

Okay, I dug into this a bit more and also in the analysis in apache/logging-log4j2#3119. Why would DebugLogger.DISABLED_LOGGER.isEnabled() return true when used with log4j-jul? DISABLED_LOGGER is created with Level.OFF, so it's always disabled (as far as DebugLogger.isEnabled is concerned - it's a final field set by DebugLogger ctor if the level is OFF.)

The comparison between the configured level and Level.OFF is not direct and goes through JUL. The code:

nashorn/src/org.openjdk.nashorn/share/classes/org/openjdk/nashorn/internal/runtime/logging/DebugLogger.java

Lines 76 to 81 in 2eb88e4

	public DebugLogger(final String loggerName, final Level loggerLevel, final boolean isQuiet) {
	this.logger = instantiateLogger(loggerName, loggerLevel);
	this.isQuiet = isQuiet;
	assert logger != null;
	this.isEnabled = getLevel() != Level.OFF;
	}

is basically equivalent to:

this.logger.setLevel(loggerLevel);
this.enabled = this.logger.getLevel() != Level.OFF;

In log4j-jul the getLevel() method always returns null. We will change that in apache/logging-log4j2#3125, but this is more of a workaround that a real fix.

OTOH, it's possible that maybe logger.isLoggable(level) check on MethodHandleFactory.java:281 might return true now? In the stack trace in apache/logging-log4j2#3119 it is invoked from MethodHandleFactory.java:376 which passed Level.INFO, so is it the case that a logger created with Level.OFF returned true from isLoggable(Level.INFO) call? Is that expected behavior in log4j-jul?

A logger can not be created with Level.OFF, because Log4j API, pretty much like SLF4J, does not have an equivalent of setLevel(). Calling Logger.setLevel() is a no-op.

If Log4j API is used together with the Log4j Core implementation, we have an option (cf. log4j2.julLoggerAdapter) that allows users to modify the configuration of Log4j Core through j.u.l.Logger. We disabled that option in 2.24.0, because it was causing problems to users (see apache/logging-log4j2#2353).

In general the usage of Logger.setLogger() is problematic, because it is hard to distinguish between:

• Legitimate usages: a class should be able to modify the configuration of its "own" logger.
• Abusive usages: some legacy libraries just set the level of the root logger to whatever they want and break users configurations.

Therefore I believe that the code that modifies the logging configuration should be in org.openjdk.nashorn.shell, which is a standalone application and should be able to control its logging configuration. The reusable org.openjdk.nashorn library should probably abstain from modifying the logging configuration.

[szegedi]

I think the initialization order here is rather brittle and unfortunate. This could all be avoided if TRACE, TRACE_RETURN, and TRACE_RETURN_VOID were looked up without going through FUNC which in this case is not really doing anything beyond exception wrapping. Basically, I'd move them before the FUNC declaration as

    private static final MethodHandle TRACE;
    private static final MethodHandle TRACE_RETURN;
    private static final MethodHandle TRACE_RETURN_VOID;
    static {
        try {
            TRACE = LOOKUP.findStatic(MethodHandleFactory.class, "traceArgs",   MethodType.methodType(void.class, DebugLogger.class, String.class, int.class, Object[].class));
            TRACE_RETURN = LOOKUP.findStatic(MethodHandleFactory.class, "traceReturn", MethodType.methodType(Object.class, DebugLogger.class, Object.class));
            TRACE_RETURN_VOID = LOOKUP.findStatic(MethodHandleFactory.class, "traceReturnVoid", MethodType.methodType(void.class, DebugLogger.class));
        } catch (NoSuchMethodException | IllegalAccessException e) {
            throw new LookupException(e);
        }
    }

And also keeping the rest of your changes.

[szegedi]

Alright, I created a JBS issue for this. If you sign the OCA we can move forward with this.

[ppkarwasz]

Alright, I created a JBS issue for this.

Thanks.

If you sign the OCA we can move forward with this.

I submitted it on Tuesday, but it still has a status of "Under review".

[szegedi]

I submitted it on Tuesday, but it still has a status of "Under review".

That's fine, I'm sure it'll work its way through in a few days.

[ppkarwasz]

I removed a couple of additional if (logger == null) and wrapped expensive log messages in a logger.isLoggable(TRACE_LEVEL).

[szegedi]

Looks great! Thank you for taking the time to do this.

[szegedi]

/sponsor

[openjdk]

@szegedi The change author (@ppkarwasz) must issue an integrate command before the integration can be sponsored.

[ppkarwasz]

/integrate auto

[openjdk]

@ppkarwasz This pull request will be automatically integrated when it is ready

[openjdk]

/integrate

[openjdk]

@openjdk[bot]
Your change (at version bec8c8b) is now ready to be sponsored by a Committer.

[szegedi]

/sponsor

[openjdk]

Going to push as commit 5e78947.

[openjdk]

@szegedi @ppkarwasz Pushed as commit 5e78947.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.