google / error-prone

Catch common Java mistakes as compile-time errors
https://errorprone.info
Apache License 2.0
6.84k stars 743 forks source link

Q: How analyze compiler crash? #3522

Open torsten-liermann opened 1 year ago

torsten-liermann commented 1 year ago

My first attempts with error prone: on Windows 10, OpenJDK 17 17.0.5, maven wrapper 3.8.6, maven-compiler-plugin 3.10.1, 2290 source classes. The compiler mojo ends up with error without error messages:

Caused by: org.apache.maven.plugin.compiler.CompilationFailureException: Compilation failure
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:1314)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:198)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2 (MojoExecutor.java:370)

How can I approach the cause of the error? Is there a debug logging? Can the code checks be activated individually to identify the faulty check?

tbroyer commented 1 year ago

My first attempts with error prone: on Windows 10, OpenJDK 17 17.0.5, maven wrapper 3.8.6, maven-compiler-plugin 3.10.1, 2290 source classes. The compiler mojo ends up with error without error messages:

Caused by: org.apache.maven.plugin.compiler.CompilationFailureException: Compilation failure
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:1314)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:198)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2 (MojoExecutor.java:370)

How can I approach the cause of the error? Is there a debug logging?

Did you check earlier in the Maven logs that the compiler itself didn't log an error? This should be no different from when you have an error in your code making it impossible to compile.

Can the code checks be activated individually to identify the faulty check?

You can disable all checks with -XepDisableAllChecks and then re-enable each selectively; see https://errorprone.info/docs/flags (and https://errorprone.info/docs/flags#maven for how to configure them in your Maven build)

torsten-liermann commented 1 year ago

-XepDisableAllChecks does not help unfortunately. The compiler does not write out any messages, see log. The project uses lombok, maybe a problem? I cannot remove Lombok from the evaluation. On an Ubuntu running WSL2, the compiler behaves no differently.

maven-compile
tbroyer commented 1 year ago

The way I debug such things (it could be that Maven is "eating" the logs too) is to run Maven with debug logs (-X) and look for the compiler arguments in the logs (line beginning with Command line options:, just be careful that arguments aren't quoted in the logs!). With these, you can:

torsten-liermann commented 1 year ago

Thank's for the Tipps. When I call the compiler from the cli I get this error:

java.lang.IllegalAccessError: class com.google.errorprone.BaseErrorProneJavaCompiler (in unnamed module @0x1a84f40f) cannot access class com.sun.tools.javac.api.BasicJavacTask (in module jdk.compiler) because module jdk.compiler does not export com.sun.tools.javac.api to unnamed module @0x1a84f40f

The CLI looks like this:

$JAVA_HOME/bin/javac --add-exports=jdk.compiler/com.sun.tools.javac.api=ALL-UNNAMED --add-exports=jdk.compiler/com.sun.tools.javac.file=ALL -UNNAMED --add-exports=jdk.compiler/com.sun.tools.javac.main=ALL-UNNAMED --add-exports=jdk.compiler/com.sun.tools.javac.model=ALL-UNNAMED -- add-exports=jdk.compiler/com.sun.tools.javac.parser=ALL-UNNAMED --add-exports=jdk.compiler/com.sun.tools.javac.processing=ALL-UNNAMED --add-exports= jdk.compiler/com.sun.tools.javac.tree=ALL-UNNAMED --add-exports=jdk.compiler/com.sun.tools.javac.util=ALL-UNNAMED --add-opens=jdk.compiler/ com.sun.tools.javac.code=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac.comp=ALL-UNNAMED --add-opens=jdk.compiler/com.sun. tools.javac.file=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac.jvm=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac. main=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac.model=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac.parser=ALL- UNNAMED --add-opens=jdk.compile r/com.sun.tools.javac.processing=ALL-UNNAMED --add-opens=jdk.compiler/com.sun.tools.javac.tree=ALL-UNNAMED --add-opens=jdk.compiler/com. sun.tools.javac.util=ALL-UNNAMED

tbroyer commented 1 year ago

The --add-exports/--add-opens should be -J--add-exports/-J--add-opens here: https://errorprone.info/docs/installation#command-line

torsten-liermann commented 1 year ago

Shit, I should have seen that myself.

The problem is here:

 error-prone version: 2.16
     BugPattern: UnusedVariable
     Stack Trace:
     java.lang.IndexOutOfBoundsException: Range [191, 158) out of bounds for length 414

Open a ticket, or is this question issue enough as a ticket?

tbroyer commented 1 year ago

That's #1250, caused by Lombok.

Workaround: disable the UnusedVariable check.

torsten-liermann commented 1 year ago

In my case -XepDisableWarningsInGeneratedCode helps.

The next problem is

BugPattern: OverrideThrowableToString
      Stack Trace:
      java.lang.AssertionError
         at com.google.errorprone.fixes.SuggestedFixes.renameMethod(SuggestedFixes.java:758)

Also lombok @ToString as described here , but unfortunately the -XepDisableWarningsInGeneratedCode option doesn't work for me here.

tbroyer commented 1 year ago

Note that those errors also depend on your version of Lombok. For this specific case, also have a look at https://errorprone.info/bugpattern/OverrideThrowableToString and possibly make it so that Lombok doesn't generate/override the toString for your classes extending Throwable (i.e. this should be actionable in your code; AFAICT, the check throws when it tries to tell you the code violates the rules)

torsten-liermann commented 1 year ago

@ToString removed for now and now the compiler runs through without any further messages as if the 2000 classes are ok. I use Lombok in the current version 1.18.24.

andreassiegel commented 1 year ago

In case someone else stumbles across this: I also had a very similar error without any details:

[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.11.0:compile (default-compile) on project: Compilation failure -> [Help 1]

In my case, the problem seems to be the Toolchains plugin that is used to set the Java version for the project. As soon as I remove the plugin and rely on the default JDK (which is actually the same as the one set via the plugin), compiling works as expected (or runs into a Lombok issue that comes with some description).

Stephan202 commented 1 year ago

@andreassiegel does running the toolchain setup with -X -Dmaven.compiler.verbose=true provide any further details?

I'm asking because coincidentally I just started playing with such a setup, and I noticed that it does not seem to be compatible with multi-line arguments to -Xplugin:ErrorProne: those trigger an invalid flag error. When I work around that using the old JDK 8 trick of moving all newlines into an XML comment, then I can successfully run Error Prone using a Toolchain-provided JDK 11 and JDK 17.

Stephan202 commented 1 year ago

^ This newline issue isn't specific to a Toolchain setup; it can also be reproduced without if one enables forking (-D-Dmaven.compiler.fork=true). I notice that in that case even -X -Dmaven.compiler.verbose=true may not uncover all issues. Manually running the forked command (module-that-fails/target/javac.sh) should help out in that case.

andreassiegel commented 1 year ago

@Stephan202 Thank you, -X -Dmaven.compiler.verbose=true sort of helped. At least it made me take another (closer) look at the output of the compiler plugin.

I used it to compare the runs with toolchains plugin and without, especially the command-line options for javac. The interesting observation is that the command apparently gets messed up when the toolchains plugin is involved.

For better readability, I added a few line-breaks.

Output without toolchains plugin:

-d <project-root>/target/classes
-classpath <project-root>/target/classes:<user-home>/.m2/repository/org/projectlombok/lombok/1.18.26/lombok-1.18.26.jar:
-sourcepath <project-root>/src/main/java:<project-root>/target/generated-sources/annotations:
-s <project-root>/target/generated-sources/annotations
-processorpath <user-home>/.m2/repository/com/google/errorprone/error_prone_core/2.18.0/error_prone_core-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_annotation/2.18.0/error_prone_annotation-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_type_annotations/2.18.0/error_prone_type_annotations-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_check_api/2.18.0/error_prone_check_api-2.18.0.jar:<user-home>/.m2/repository/io/github/java-diff-utils/java-diff-utils/4.0/java-diff-utils-4.0.jar:<user-home>/.m2/repository/org/eclipse/jgit/org.eclipse.jgit/4.4.1.201607150455-r/org.eclipse.jgit-4.4.1.201607150455-r.jar:<user-home>/.m2/repository/com/github/kevinstern/software-and-algorithms/1.0/software-and-algorithms-1.0.jar:<user-home>/.m2/repository/com/github/ben-manes/caffeine/caffeine/3.0.5/caffeine-3.0.5.jar:<user-home>/.m2/repository/org/pcollections/pcollections/3.1.4/pcollections-3.1.4.jar:<user-home>/.m2/repository/com/google/guava/guava/31.0.1-jre/guava-31.0.1-jre.jar:<user-home>/.m2/repository/com/google/guava/failureaccess/1.0.1/failureaccess-1.0.1.jar:<user-home>/.m2/repository/com/google/guava/listenablefuture/9999.0-empty-to-avoid-conflict-with-guava/listenablefuture-9999.0-empty-to-avoid-conflict-with-guava.jar:<user-home>/.m2/repository/org/checkerframework/checker-qual/3.12.0/checker-qual-3.12.0.jar:<user-home>/.m2/repository/com/google/j2objc/j2objc-annotations/1.3/j2objc-annotations-1.3.jar:<user-home>/.m2/repository/com/google/auto/auto-common/1.2.1/auto-common-1.2.1.jar:<user-home>/.m2/repository/com/google/code/findbugs/jsr305/3.0.2/jsr305-3.0.2.jar:<user-home>/.m2/repository/org/checkerframework/dataflow-errorprone/3.27.0/dataflow-errorprone-3.27.0.jar:<user-home>/.m2/repository/com/google/auto/value/auto-value-annotations/1.9/auto-value-annotations-1.9.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_annotations/2.18.0/error_prone_annotations-2.18.0.jar:<user-home>/.m2/repository/com/google/protobuf/protobuf-java/3.19.2/protobuf-java-3.19.2.jar:<user-home>/.m2/repository/com/google/auto/service/auto-service-annotations/1.0.1/auto-service-annotations-1.0.1.jar:<user-home>/.m2/repository/javax/inject/javax.inject/1/javax.inject-1.jar:<user-home>/.m2/repository/org/projectlombok/lombok/1.18.26/lombok-1.18.26.jar:
-g
-verbose
--release 17
-encoding UTF-8
-XDcompilePolicy=simple
-Xplugin:ErrorProne

When the toolchains plugin is involved, the output looks as follows:

-d <project-root>/target/classes
-classpath <project-root>/target/classes:<user-home>/.m2/repository/org/projectlombok/lombok/1.18.26/lombok-1.18.26.jar:
-sourcepath <project-root>/src/main/java:<project-root>/target/generated-sources/annotations:
<project-root>/src/main/java/ShortSet.java <project-root>/src/main/java/LombokTestClass.java
-s <project-root>/target/generated-sources/annotations
-processorpath <user-home>/.m2/repository/com/google/errorprone/error_prone_core/2.18.0/error_prone_core-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_annotation/2.18.0/error_prone_annotation-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_type_annotations/2.18.0/error_prone_type_annotations-2.18.0.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_check_api/2.18.0/error_prone_check_api-2.18.0.jar:<user-home>/.m2/repository/io/github/java-diff-utils/java-diff-utils/4.0/java-diff-utils-4.0.jar:<user-home>/.m2/repository/org/eclipse/jgit/org.eclipse.jgit/4.4.1.201607150455-r/org.eclipse.jgit-4.4.1.201607150455-r.jar:<user-home>/.m2/repository/com/github/kevinstern/software-and-algorithms/1.0/software-and-algorithms-1.0.jar:<user-home>/.m2/repository/com/github/ben-manes/caffeine/caffeine/3.0.5/caffeine-3.0.5.jar:<user-home>/.m2/repository/org/pcollections/pcollections/3.1.4/pcollections-3.1.4.jar:<user-home>/.m2/repository/com/google/guava/guava/31.0.1-jre/guava-31.0.1-jre.jar:<user-home>/.m2/repository/com/google/guava/failureaccess/1.0.1/failureaccess-1.0.1.jar:<user-home>/.m2/repository/com/google/guava/listenablefuture/9999.0-empty-to-avoid-conflict-with-guava/listenablefuture-9999.0-empty-to-avoid-conflict-with-guava.jar:<user-home>/.m2/repository/org/checkerframework/checker-qual/3.12.0/checker-qual-3.12.0.jar:<user-home>/.m2/repository/com/google/j2objc/j2objc-annotations/1.3/j2objc-annotations-1.3.jar:<user-home>/.m2/repository/com/google/auto/auto-common/1.2.1/auto-common-1.2.1.jar:<user-home>/.m2/repository/com/google/code/findbugs/jsr305/3.0.2/jsr305-3.0.2.jar:<user-home>/.m2/repository/org/checkerframework/dataflow-errorprone/3.27.0/dataflow-errorprone-3.27.0.jar:<user-home>/.m2/repository/com/google/auto/value/auto-value-annotations/1.9/auto-value-annotations-1.9.jar:<user-home>/.m2/repository/com/google/errorprone/error_prone_annotations/2.18.0/error_prone_annotations-2.18.0.jar:<user-home>/.m2/repository/com/google/protobuf/protobuf-java/3.19.2/protobuf-java-3.19.2.jar:<user-home>/.m2/repository/com/google/auto/service/auto-service-annotations/1.0.1/auto-service-annotations-1.0.1.jar:<user-home>/.m2/repository/javax/inject/javax.inject/1/javax.inject-1.jar:<user-home>/.m2/repository/org/projectlombok/lombok/1.18.26/lombok-1.18.26.jar:
-g
-verbose
--release 17
-encoding UTF-8
-XDcompilePolicy=simple
-Xplugin:ErrorProne

Note the line between -sourcepath and -s: The source file paths get added in the middle of the javac command-line arguments, right before the arguments that seem to be specific to error-prone follow.

So, at least in my case, multi-line arguments for ErrorProne aren't an issue.

I just wonder what causes that difference, and how to fix it (or if that actually is an issue at all).

Edit: After playing around a bit more, under the assumption that the plugin configuration itself shouldn't be the problem since you got it working with a toolchain, I just tried another one -- and it worked. Thus, the problem actually is the toolchain (configuration) itself. My configuration for Temurin JDK 17 and Temurin JDK 19 are both not working but Temurin JDK 11 and Microsoft OpenJDK 11 are.

Calling javac directly with JDK 17 or 19 leads to this error:

Exception in thread "main" java.lang.IllegalAccessError: class com.google.errorprone.BaseErrorProneJavaCompiler (in unnamed module @0x30c15d8b) cannot access class com.sun.tools.javac.api.BasicJavacTask (in module jdk.compiler) because module jdk.compiler does not export com.sun.tools.javac.api to unnamed module @0x30c15d8b
    at com.google.errorprone.BaseErrorProneJavaCompiler.addTaskListener(BaseErrorProneJavaCompiler.java:95)
    at com.google.errorprone.ErrorProneJavacPlugin.init(ErrorProneJavacPlugin.java:34)
    at jdk.compiler/com.sun.tools.javac.api.BasicJavacTask.initPlugin(BasicJavacTask.java:255)
    at jdk.compiler/com.sun.tools.javac.api.BasicJavacTask.initPlugins(BasicJavacTask.java:229)
    at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:292)
    at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:176)
    at jdk.compiler/com.sun.tools.javac.Main.compile(Main.java:64)
    at jdk.compiler/com.sun.tools.javac.Main.main(Main.java:50)

This does not occur when JDK 11 is used. The reason for that is that the additional configuration in jvm.config (as described here) was not taken into account.

So I finally got it working by defining the flags in the compilerArgs of the compiler plugin configuration:

<compilerArgs>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.api=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.file=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.main=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.model=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.parser=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.processing=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.tree=ALL-UNNAMED</arg>
  <arg>-J--add-exports=jdk.compiler/com.sun.tools.javac.util=ALL-UNNAMED</arg>
  <arg>-J--add-opens=jdk.compiler/com.sun.tools.javac.code=ALL-UNNAMED</arg>
  <arg>-J--add-opens=jdk.compiler/com.sun.tools.javac.comp=ALL-UNNAMED</arg>
  <arg>-XDcompilePolicy=simple</arg>
  <arg>-Xplugin:ErrorProne</arg>
</compilerArgs>
Stephan202 commented 1 year ago

Very nice that you figured it out @andreassiegel!

For the more general issue that compiler failures sometimes happen without clear output, codehaus-plexus/plexus-compiler#66 may be an issue to keep an eye on.

hisener commented 1 year ago

Sorry for resurrecting the issue, but I am also looking for general advice on debugging a compiler failure.

We see intermittent compilation errors in a Maven project with >450 modules when Error Prone is enabled. It doesn't prove the issue is in Error Prone, but it may be more likely to happen when Error Prone is enabled. I couldn't reproduce when Error Prone is enabled, but all bug patterns are disabled (-XepDisableAllChecks). Errors point to valid Java code. For instance,

[parsing started SimpleFileObject[...]]
[parsing completed 1ms]
[parsing started SimpleFileObject[...]]
[parsing completed 0ms]
[loading modules/jdk.net/module-info.class]
...
[loading modules/java.base/module-info.class]
[loading modules/jdk.management.jfr/module-info.class]
[total 128ms]
Raw diagnostic: [...].java:32: error: ';' expected
  public final com.google.protobuf.UnknownFieldSet
                  ^
Raw diagnostic: [...].java:48: error: ';' expected
      while (!done) {
                   ^

It seems it fails at the CompileState#ENTER state here. But sometimes it fails during/after annotation processing. Example:

[loading modules/java.base/java/lang/SuppressWarnings.class]
[loading .m2/com/google/guava/guava/31.1-jre/guava-31.1-jre.jar(/com/google/common/annotations/GwtCompatible.class)]
...
[loading modules/java.base/java/lang/Class.class]
Round 1:
    input files: {[...]}
    annotations: [java.lang.Deprecated, java.lang.Override, java.lang.SuppressWarnings, org.jetbrains.annotations.NotNull]
    last round: false
Round 2:
    input files: {}
    annotations: []
    last round: true
[total 1947ms]
Raw diagnostic: [...].java:418: error: cannot find symbol
  java.util.List<com.dd.[...]> 
           ^
  symbol:   class RWCa
  location: package java.util
Raw diagnostic: [...].java:497: error: package com.dd.[...] does not exist
  com.dd.[...].ClassName getClassName();
              ^

There is no pattern for error either. There are jobs we got <identifier> expected, not a statement, invalid method declaration; return type required, etc.

There are also errors that might indicate a potential race condition:

IIUC, in a multi-threaded build, maven-compiler-plugin creates a new javax.tools.JavaCompiler instance for each compilation. Also, switching to alwaysNew maven-compiler-plugin compiler reuse strategy didn't help. There might be a shared non-thread safe instance they use. 🤷‍♂️

I disabled a few things and made sure that the source files were not corrupted before the Maven build, but still, there are a few layers that can cause the issue:

It usually happens when we build all (or almost all) modules in a CI job. I still couldn't reproduce it locally, but I can reproduce it 2-3% of the time on CI for a full build. The overall failure rate is less than 1%. But it's still quite annoying and confusing for developers working on the project.

So, I would appreciate some pointers on debugging it further or how to reproduce it locally.

tbroyer commented 1 year ago

You could probably rule out the "shared non-thread safe instance" option by configuring maven-compiler-plugin to fork (you'll probably have to copy the --add-opens/--add-exports to <compilerArgs>, prefixing them with -J; see above), as m-compiler-p will then fork a new JVM for each "task". Your builds will take longer, but if you still reproduce the issue that way then it means it's not a "shared non-thread safe instance" issue.

Also, are you using Maven's parallel builds? If so, you could also try disabling them to possibly rule out concurrency issues.

hisener commented 1 year ago

Thanks for the swift answer!

You could probably rule out the "shared non-thread safe instance" option by configuring maven-compiler-plugin to fork (you'll probably have to copy the --add-opens/--add-exports to <compilerArgs>, prefixing them with -J; see above), as m-compiler-p will then fork a new JVM for each "task". Your builds will take longer, but if you still reproduce the issue that way then it means it's not a "shared non-thread safe instance" issue.

That's a good point. I will try that next.

Also, are you using Maven's parallel builds? If so, you could also try disabling them to possibly rule out concurrency issues.

Yes, it's a parallel build with thread count of 4.

hisener commented 1 year ago

Sorry for the late response. Indeed, forking javac indicates it's a concurrency issue. But we cannot afford forking javac for 450+ modules. It's extremely slow compared to in-process compilation.

I enabled forking for the module where we get most of the errors to see if others will start failing due to intermittent compilation errors. And there was one interesting failure:

Compilation failure: 
08:14:03 [ERROR] cannot access DefaultSta.module-info
08:14:03 [ERROR]   bad class file: modules/jdk.jstatd/module-info.class
08:14:03 [ERROR]     module name jdk.jstatd does not match expected name DefaultSta
08:14:03 [ERROR]     Please remove or make sure it appears in the correct subdirectory of the classpath.
08:14:03 [ERROR] cannot access StateProvidert.module-info
08:14:03 [ERROR]   bad class file: modules/jdk.management/module-info.class
08:14:03 [ERROR]     module name jdk.management does not match expected name StateProvidert
08:14:03 [ERROR]     Please remove or make sure it appears in the correct subdirectory of the classpath.
...

There is no module called DefaultSta; however, there is a class called DefaultStateKey in another Maven module that we depend on. 🤔 The same goes for StateProvidert.

I think the error comes from this line: https://github.com/openjdk/jdk/blob/jdk-17%2B19/src/jdk.compiler/share/classes/com/sun/tools/javac/jvm/ClassReader.java#L1087-L1089