Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Intermittent Stream closed exception after upgrading to 1.10.2 #1572

Closed
bvolpato opened this issue Aug 3, 2023 · 16 comments
Closed

Intermittent Stream closed exception after upgrading to 1.10.2 #1572

bvolpato opened this issue Aug 3, 2023 · 16 comments
Assignees

Comments

@bvolpato
Copy link

bvolpato commented Aug 3, 2023

Hello!

We recently started observing an intermittent error after upgrading from 1.8.2 to 1.10.2 (GoogleCloudPlatform/DataflowTemplates#929).

I suspect it might be related to some racing/concurrency issues, as it happens sporadically and we are running Maven using multiple threads (mvn -T8 ...). It is either very hard to get when running in a single thread (I tried a bunch of times and it didn't repro), or parallelism is actually the issue.

Build https://github.com/GoogleCloudPlatform/DataflowTemplates/actions/runs/5734638367/job/15541176096?pr=934

Full stacktrace:

Error:  Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.6.2:compile (default-compile) on project pubsub-to-redis: Fatal error compiling: autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.6.2:compile (default-compile) on project pubsub-to-redis: Fatal error compiling
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:215)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: org.apache.maven.plugin.MojoExecutionException: Fatal error compiling
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:963)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:158)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: org.codehaus.plexus.compiler.CompilerException: autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed
    at org.codehaus.plexus.compiler.javac.JavaxToolsCompiler.compileInProcess (JavaxToolsCompiler.java:173)
    at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile (JavacCompiler.java:174)
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:952)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:158)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: java.lang.RuntimeException: autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed
    at com.sun.tools.javac.api.JavacTaskImpl.handleExceptions (JavacTaskImpl.java:163)
    at com.sun.tools.javac.api.JavacTaskImpl.doCall (JavacTaskImpl.java:100)
    at com.sun.tools.javac.api.JavacTaskImpl.call (JavacTaskImpl.java:94)
    at org.codehaus.plexus.compiler.javac.JavaxToolsCompiler.compileInProcess (JavaxToolsCompiler.java:126)
    at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile (JavacCompiler.java:174)
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:952)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:158)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed
    at autovalue.shaded.com.google.escapevelocity.Node.evaluationException (Node.java:59)
    at autovalue.shaded.com.google.escapevelocity.ParseNode.render (ParseNode.java:65)
    at autovalue.shaded.com.google.escapevelocity.Node$Cons.render (Node.java:91)
    at autovalue.shaded.com.google.escapevelocity.DirectiveNode$IfNode.render (DirectiveNode.java:103)
    at autovalue.shaded.com.google.escapevelocity.Node$Cons.render (Node.java:91)
    at autovalue.shaded.com.google.escapevelocity.Template.render (Template.java:189)
    at autovalue.shaded.com.google.escapevelocity.Template.evaluate (Template.java:179)
    at com.google.auto.value.processor.TemplateVars.toText (TemplateVars.java:99)
    at com.google.auto.value.processor.AutoValueProcessor.processType (AutoValueProcessor.java:274)
    at com.google.auto.value.processor.AutoValueishProcessor.process (AutoValueishProcessor.java:441)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.callProcessor (JavacProcessingEnvironment.java:985)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.discoverAndRunProcs (JavacProcessingEnvironment.java:901)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment$Round.run (JavacProcessingEnvironment.java:1227)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.doProcessing (JavacProcessingEnvironment.java:1340)
    at com.sun.tools.javac.main.JavaCompiler.processAnnotations (JavaCompiler.java:1254)
    at com.sun.tools.javac.main.JavaCompiler.compile (JavaCompiler.java:936)
    at com.sun.tools.javac.api.JavacTaskImpl.lambda$doCall$0 (JavacTaskImpl.java:104)
    at com.sun.tools.javac.api.JavacTaskImpl.handleExceptions (JavacTaskImpl.java:147)
    at com.sun.tools.javac.api.JavacTaskImpl.doCall (JavacTaskImpl.java:100)
    at com.sun.tools.javac.api.JavacTaskImpl.call (JavacTaskImpl.java:94)
    at org.codehaus.plexus.compiler.javac.JavaxToolsCompiler.compileInProcess (JavaxToolsCompiler.java:126)
    at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile (JavacCompiler.java:174)
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:952)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:158)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Caused by: java.io.IOException: Stream closed
    at java.util.zip.InflaterInputStream.ensureOpen (InflaterInputStream.java:68)
    at java.util.zip.InflaterInputStream.read (InflaterInputStream.java:143)
    at java.io.FilterInputStream.read (FilterInputStream.java:133)
    at sun.nio.cs.StreamDecoder.readBytes (StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead (StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read (StreamDecoder.java:178)
    at java.io.InputStreamReader.read (InputStreamReader.java:181)
    at java.io.BufferedReader.fill (BufferedReader.java:161)
    at java.io.BufferedReader.read (BufferedReader.java:182)
    at java.io.LineNumberReader.read (LineNumberReader.java:126)
    at autovalue.shaded.com.google.escapevelocity.Parser.next (Parser.java:144)
    at autovalue.shaded.com.google.escapevelocity.Parser.skipSpace (Parser.java:171)
    at autovalue.shaded.com.google.escapevelocity.Parser.expect (Parser.java:189)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseIfOrElseIf (Parser.java:418)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective (Parser.java:370)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseNode (Parser.java:271)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop (Parser.java:223)
    at autovalue.shaded.com.google.escapevelocity.Parser.skipNewlineAndParseToStop (Parser.java:251)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseForEach (Parser.java:476)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective (Parser.java:378)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseNode (Parser.java:271)
    at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop (Parser.java:223)
    at autovalue.shaded.com.google.escapevelocity.Parser.parse (Parser.java:128)
    at autovalue.shaded.com.google.escapevelocity.Template.parseFrom (Template.java:147)
    at autovalue.shaded.com.google.escapevelocity.ParseNode.render (ParseNode.java:62)
    at autovalue.shaded.com.google.escapevelocity.Node$Cons.render (Node.java:91)
    at autovalue.shaded.com.google.escapevelocity.DirectiveNode$IfNode.render (DirectiveNode.java:103)
    at autovalue.shaded.com.google.escapevelocity.Node$Cons.render (Node.java:91)
    at autovalue.shaded.com.google.escapevelocity.Template.render (Template.java:189)
    at autovalue.shaded.com.google.escapevelocity.Template.evaluate (Template.java:179)
    at com.google.auto.value.processor.TemplateVars.toText (TemplateVars.java:99)
    at com.google.auto.value.processor.AutoValueProcessor.processType (AutoValueProcessor.java:274)
    at com.google.auto.value.processor.AutoValueishProcessor.process (AutoValueishProcessor.java:441)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.callProcessor (JavacProcessingEnvironment.java:985)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.discoverAndRunProcs (JavacProcessingEnvironment.java:901)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment$Round.run (JavacProcessingEnvironment.java:1227)
    at com.sun.tools.javac.processing.JavacProcessingEnvironment.doProcessing (JavacProcessingEnvironment.java:1340)
    at com.sun.tools.javac.main.JavaCompiler.processAnnotations (JavaCompiler.java:1254)
    at com.sun.tools.javac.main.JavaCompiler.compile (JavaCompiler.java:936)
    at com.sun.tools.javac.api.JavacTaskImpl.lambda$doCall$0 (JavacTaskImpl.java:104)
    at com.sun.tools.javac.api.JavacTaskImpl.handleExceptions (JavacTaskImpl.java:147)
    at com.sun.tools.javac.api.JavacTaskImpl.doCall (JavacTaskImpl.java:100)
    at com.sun.tools.javac.api.JavacTaskImpl.call (JavacTaskImpl.java:94)
    at org.codehaus.plexus.compiler.javac.JavaxToolsCompiler.compileInProcess (JavaxToolsCompiler.java:126)
    at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile (JavacCompiler.java:174)
    at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute (AbstractCompilerMojo.java:952)
    at org.apache.maven.plugin.compiler.CompilerMojo.execute (CompilerMojo.java:158)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:200)
    at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call (MultiThreadedBuilder.java:196)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)
Error:  
Error:  Re-run Maven using the -X switch to enable full debug logging.
Error:  
Error:  For more information about the errors and possible solutions, please read the following articles:
Error:  [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
Error:  
Error:  After correcting the problems, you can resume the build with the command
Error:    mvn <goals> -rf :pubsub-to-redis
@cgdecker
Copy link
Member

cgdecker commented Aug 3, 2023

@eamonnmcmanus

I dug around in the code for a bit to see what might have changed between 1.8.2 and 1.10.2 that could be a cause for this, and what looked most likely to me is the change to parse files for #parse nodes at template evaluation time rather than template parse time.

It seems like that could be a problem here because AutoValueTemplateVars holds a pre-parsed static final Template for autovalue.vm, which will then need to try to open and parse (and cache) equalshashcode.vm (always) and builder.vm (if there's a builder -- this seems to be where the exception is occurring in this case). The issue then could have to do with how TemplateVars.class.getResourceAsStream is used to to open the streams to read those from.

All that said, I'm not sure why opening that stream seemingly must be succeeding in this stack trace and the exception is then occurring while reading from from it. Maybe something is closing the original jar stream that the static reference to TemplateVars.class was loaded from, making the streams opened from it with getResourceAsStream also closed?

@eamonnmcmanus eamonnmcmanus self-assigned this Aug 3, 2023
alexeykukuku pushed a commit to alexeykukuku/DataflowTemplates that referenced this issue Aug 3, 2023
@eamonnmcmanus
Copy link
Member

Thanks @cgdecker, I think your theory is correct.

From the stack traces, it looks like this is happening on Java 8. I think the issue is JDK-6947916, which was fixed in Java 9. We already have a workaround but as Colin notes that only applies when the original autovalue.vm is read. The #parse happens later, outside the try/catch where the workaround is active.

I put a lot of effort into making this workaround, including a ridiculously complicated regression test, then unknowingly undid it all with the change Colin mentions.

While it's probably possible to come up with a new workaround, I think it would be a lot easier just to build with a more recent JDK. JDK 8 was released in 2014 and is more or less EOL now. Unless you can confirm that it is in fact a more recent JDK? (I'm assuming it's 8 because there are no module names in the stack traces.)

@eamonnmcmanus
Copy link
Member

(You can still build with --target 8 to produce Java-8-compatible .class files.)

@eamonnmcmanus eamonnmcmanus added type=defect Bug, not working as expected Status: accepted labels Aug 3, 2023
@cgdecker
Copy link
Member

cgdecker commented Aug 3, 2023

Looking at the failed build link, it looks like Maven should be compiling with JDK 11 in this case:

Run actions/setup-java@a12e082d834968c1847f782019214fadd20719f6
  with:
    distribution: zulu
    java-version: 11
    java-package: jdk
    architecture: x64
    check-latest: false
    server-id: github
    server-username: GITHUB_ACTOR
    server-password: GITHUB_TOKEN
    overwrite-settings: true
    job-status: success
  env:
    MAVEN_OPTS: -Dorg.slf4j.simpleLogger.log.org.apache.maven.plugins.shade=error
    GOROOT: /home/runner/actions-runner/_work/_tool/go/1.17.13/x64
Resolved Java 11.0.19+7 from tool-cache
Setting Java 11.0.19+7 as the default

Specifically with:

Java configuration:
  Distribution: zulu
  Version: 11.0.19+7
  Path: /home/runner/actions-runner/_work/_tool/Java_Zulu_jdk/11.0.19-7/x64

I wonder if changing the distribution to something else (oracle or adopt maybe?) would change anything.

@bvolpato
Copy link
Author

bvolpato commented Aug 3, 2023

Thanks for looking into this!

Right, it should be Java 11.

I got locally too with

openjdk version "11.0.17" 2022-10-18
OpenJDK Runtime Environment Temurin-11.0.17+8 (build 11.0.17+8)
OpenJDK 64-Bit Server VM Temurin-11.0.17+8 (build 11.0.17+8, mixed mode)

After running while mvn -T32 clean compile -DskipTests -e; do done at DataflowTemplates for a couple of minutes.

It's hard to bisect because it takes a bit to run, but I am pretty confident it is not happening with a single thread (or the probability is minimal), as the loop ran for hours with -T1.

Appreciate you guys looking -- but note that I understand this is a very specific use-case and this is not urgent. We reverted to 1.8.2 for the time being.

@eamonnmcmanus
Copy link
Member

eamonnmcmanus commented Aug 3, 2023

I'm still puzzled at the absence of module names in those stack traces. Could you do this experiment in your environment?

$ jshell
|  Welcome to JShell -- Version 11.0.17
|  For an introduction type: /help intro

jshell> new Throwable().printStackTrace()
java.lang.Throwable
	at REPL.$JShell$11.do_it$($JShell$11.java:5)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at jdk.jshell/jdk.jshell.execution.DirectExecutionControl.invoke(DirectExecutionControl.java:209)
        ...

It's those java.base/ that I would expect to see in a stack trace from the JDK 11 compiler. Unless the Zulu JDK doesn't do that?

I'm persisting here just because it still seems like a big coincidence that (1) the stack traces look like Java 8 and (2) the symptoms correspond exactly to a bug that was fixed in Java 9.

@cgdecker
Copy link
Member

cgdecker commented Aug 3, 2023

Curiously, I just ran the jshell binary from zulu11.66.15-ca-jdk11.0.20-linux_x64 and saw module names as expected, so I do wonder if something weird is going on.

@eamonnmcmanus
Copy link
Member

For example, if the pom.xml were doing something like this then the compilation could end up using JDK 8 even though Maven itself is running with JDK 11.

@honnix
Copy link

honnix commented Sep 6, 2023

We also hit this problem quite often these day. Is there a plan to get this prioritized a bit? Thank you.

@eamonnmcmanus
Copy link
Member

We also hit this problem quite often these day. Is there a plan to get this prioritized a bit? Thank you.

Can you confirm whether you are using JDK 8 or a later JDK version?

@honnix
Copy link

honnix commented Sep 6, 2023

I can confirm we use Java 11 and compile with 11 as release target as well. We have Maven parallell build enabled.

@eamonnmcmanus
Copy link
Member

OK. If you have an exception stack-trace, can you show it? I'm curious if it contains module names, as I mentioned in an earlier comment. But I think it is probably possible to rework the code so that the existing workaround is applied more generally.

@honnix
Copy link

honnix commented Sep 6, 2023

Sure. There it is:

error: [AutoValueException] @AutoValue processor threw an exception: autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Node.evaluationException(Node.java:59)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.ParseNode.render(ParseNode.java:65)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Node$Cons.render(Node.java:91)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.DirectiveNode$IfNode.render(DirectiveNode.java:103)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Node$Cons.render(Node.java:91)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Template.render(Template.java:189)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Template.evaluate(Template.java:179)
14:58:41    	at com.google.auto.value.processor.TemplateVars.toText(TemplateVars.java:99)
14:58:41    	at com.google.auto.value.processor.AutoValueProcessor.processType(AutoValueProcessor.java:274)
14:58:41    	at com.google.auto.value.processor.AutoValueishProcessor.process(AutoValueishProcessor.java:441)
14:58:41    	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.callProcessor(JavacProcessingEnvironment.java:985)
14:58:41    	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.discoverAndRunProcs(JavacProcessingEnvironment.java:901)
14:58:41    	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment$Round.run(JavacProcessingEnvironment.java:1227)
14:58:41    	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.doProcessing(JavacProcessingEnvironment.java:1340)
14:58:41    	at jdk.compiler/com.sun.tools.javac.main.JavaCompiler.processAnnotations(JavaCompiler.java:1254)
14:58:41    	at jdk.compiler/com.sun.tools.javac.main.JavaCompiler.compile(JavaCompiler.java:936)
14:58:41    	at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:311)
14:58:41    	at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:170)
14:58:41    	at jdk.compiler/com.sun.tools.javac.Main.compile(Main.java:75)
14:58:41    	at jdk.internal.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
14:58:41    	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:58:41    	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
14:58:41    	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcess0(JavacCompiler.java:700)
14:58:41    	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcessWithProperClassloader(JavacCompiler.java:681)
14:58:41    	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcess(JavacCompiler.java:670)
14:58:41    	at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile(JavacCompiler.java:187)
14:58:41    	at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute(AbstractCompilerMojo.java:1140)
14:58:41    	at org.apache.maven.plugin.compiler.CompilerMojo.execute(CompilerMojo.java:193)
14:58:41    	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:126)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:342)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:330)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:213)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:175)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.access$000(MojoExecutor.java:76)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor$1.run(MojoExecutor.java:163)
14:58:41    	at org.apache.maven.plugin.DefaultMojosExecutionStrategy.execute(DefaultMojosExecutionStrategy.java:39)
14:58:41    	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:160)
14:58:41    	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:105)
14:58:41    	at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:193)
14:58:41    	at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:180)
14:58:41    	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
14:58:41    	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
14:58:41    	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
14:58:41    	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
14:58:41    	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
14:58:41    	at java.base/java.lang.Thread.run(Thread.java:829)
14:58:41    Caused by: java.io.IOException: Stream closed
14:58:41    	at java.base/java.util.zip.InflaterInputStream.ensureOpen(InflaterInputStream.java:68)
14:58:41    	at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:143)
14:58:41    	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
14:58:41    	at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
14:58:41    	at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
14:58:41    	at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
14:58:41    	at java.base/java.io.InputStreamReader.read(InputStreamReader.java:181)
14:58:41    	at java.base/java.io.BufferedReader.fill(BufferedReader.java:161)
14:58:41    	at java.base/java.io.BufferedReader.read(BufferedReader.java:182)
14:58:41    	at java.base/java.io.LineNumberReader.read(LineNumberReader.java:126)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.next(Parser.java:144)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.skipSpace(Parser.java:171)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.expect(Parser.java:189)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseIfOrElseIf(Parser.java:418)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective(Parser.java:370)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseNode(Parser.java:271)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop(Parser.java:223)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.skipNewlineAndParseToStop(Parser.java:251)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseForEach(Parser.java:476)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective(Parser.java:378)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseNode(Parser.java:271)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop(Parser.java:223)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Parser.parse(Parser.java:128)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.Template.parseFrom(Template.java:147)
14:58:41    	at autovalue.shaded.com.google.escapevelocity.ParseNode.render(ParseNode.java:62)
14:58:41    	... 44 more
14:58:41  [�[1;31mERROR�[m] autovalue.shaded.com.google.escapevelocity.EvaluationException: In expression on line 192 of autovalue.vm: java.io.IOException: Stream closed
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Node.evaluationException(Node.java:59)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.ParseNode.render(ParseNode.java:65)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Node$Cons.render(Node.java:91)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.DirectiveNode$IfNode.render(DirectiveNode.java:103)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Node$Cons.render(Node.java:91)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Template.render(Template.java:189)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Template.evaluate(Template.java:179)
14:58:41  	at com.google.auto.value.processor.TemplateVars.toText(TemplateVars.java:99)
14:58:41  	at com.google.auto.value.processor.AutoValueProcessor.processType(AutoValueProcessor.java:274)
14:58:41  	at com.google.auto.value.processor.AutoValueishProcessor.process(AutoValueishProcessor.java:441)
14:58:41  	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.callProcessor(JavacProcessingEnvironment.java:985)
14:58:41  	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.discoverAndRunProcs(JavacProcessingEnvironment.java:901)
14:58:41  	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment$Round.run(JavacProcessingEnvironment.java:1227)
14:58:41  	at jdk.compiler/com.sun.tools.javac.processing.JavacProcessingEnvironment.doProcessing(JavacProcessingEnvironment.java:1340)
14:58:41  	at jdk.compiler/com.sun.tools.javac.main.JavaCompiler.processAnnotations(JavaCompiler.java:1254)
14:58:41  	at jdk.compiler/com.sun.tools.javac.main.JavaCompiler.compile(JavaCompiler.java:936)
14:58:41  	at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:311)
14:58:41  	at jdk.compiler/com.sun.tools.javac.main.Main.compile(Main.java:170)
14:58:41  	at jdk.compiler/com.sun.tools.javac.Main.compile(Main.java:75)
14:58:41  	at jdk.internal.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
14:58:41  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:58:41  	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
14:58:41  	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcess0(JavacCompiler.java:700)
14:58:41  	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcessWithProperClassloader(JavacCompiler.java:681)
14:58:41  	at org.codehaus.plexus.compiler.javac.JavacCompiler.compileInProcess(JavacCompiler.java:670)
14:58:41  	at org.codehaus.plexus.compiler.javac.JavacCompiler.performCompile(JavacCompiler.java:187)
14:58:41  	at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute(AbstractCompilerMojo.java:1140)
14:58:41  	at org.apache.maven.plugin.compiler.CompilerMojo.execute(CompilerMojo.java:193)
14:58:41  	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:126)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:342)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:330)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:213)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:175)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.access$000(MojoExecutor.java:76)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor$1.run(MojoExecutor.java:163)
14:58:41  	at org.apache.maven.plugin.DefaultMojosExecutionStrategy.execute(DefaultMojosExecutionStrategy.java:39)
14:58:41  	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:160)
14:58:41  	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:105)
14:58:41  	at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:193)
14:58:41  	at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:180)
14:58:41  	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
14:58:41  	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
14:58:41  	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
14:58:41  	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
14:58:41  	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
14:58:41  	at java.base/java.lang.Thread.run(Thread.java:829)
14:58:41  Caused by: java.io.IOException: Stream closed
14:58:41  	at java.base/java.util.zip.InflaterInputStream.ensureOpen(InflaterInputStream.java:68)
14:58:41  	at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:143)
14:58:41  	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
14:58:41  	at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
14:58:41  	at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
14:58:41  	at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
14:58:41  	at java.base/java.io.InputStreamReader.read(InputStreamReader.java:181)
14:58:41  	at java.base/java.io.BufferedReader.fill(BufferedReader.java:161)
14:58:41  	at java.base/java.io.BufferedReader.read(BufferedReader.java:182)
14:58:41  	at java.base/java.io.LineNumberReader.read(LineNumberReader.java:126)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.next(Parser.java:144)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.skipSpace(Parser.java:171)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.expect(Parser.java:189)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseIfOrElseIf(Parser.java:418)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective(Parser.java:370)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseNode(Parser.java:271)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop(Parser.java:223)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.skipNewlineAndParseToStop(Parser.java:251)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseForEach(Parser.java:476)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseDirective(Parser.java:378)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseNode(Parser.java:271)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parseToStop(Parser.java:223)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Parser.parse(Parser.java:128)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.Template.parseFrom(Template.java:147)
14:58:41  	at autovalue.shaded.com.google.escapevelocity.ParseNode.render(ParseNode.java:62)
14:58:41  	... 44 more

@eamonnmcmanus
Copy link
Member

eamonnmcmanus commented Sep 6, 2023

Huh. That certainly does look like a Java 11 stacktrace. But JDK-6947916 is supposed to be fixed there. So perhaps there is another related issue? Anyway, I think this can be worked around and will look into that.

copybara-service bot pushed a commit that referenced this issue Sep 7, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback.
PiperOrigin-RevId: 563251940
copybara-service bot pushed a commit that referenced this issue Sep 7, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback.
PiperOrigin-RevId: 563251940
copybara-service bot pushed a commit that referenced this issue Sep 8, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback. See #1572.
PiperOrigin-RevId: 563251940
copybara-service bot pushed a commit that referenced this issue Sep 8, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback. See #1572.
PiperOrigin-RevId: 563251940
copybara-service bot pushed a commit that referenced this issue Sep 8, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback. See #1572.
PiperOrigin-RevId: 563251940
copybara-service bot pushed a commit that referenced this issue Sep 8, 2023
We now always read template resources directly from the jar file containing them, rather than initially trying to use `getResourceAsStream`. That can trigger [JDK-6947916](https://bugs.openjdk.org/browse/JDK-6947916) and our existing fallback-to-workaround logic was ineffective with recent versions of EscapeVelocity. Even though the JDK bug was supposedly fixed in JDK 9 and later JDK 8 updates, people are still reporting issues with AutoValue that look exactly like it.

Reading directly from the jar file should not be _too_ inefficient, and each read should only happen once per compilation, no matter how many `@AutoValue` classes there are in the compilation.

Fixes #1572.

RELNOTES=A workaround for a JDK bug with reading jar resources has been extended so it always applies, rather than just as a fallback. See #1572.
PiperOrigin-RevId: 563251940
@eamonnmcmanus
Copy link
Member

I made it so that we no longer ever use JarURLConnection to read the resources (template files) that AutoValue needs. Instead, we always open the jar where the AutoValue code lives explicitly, and read the resources out of it. That's probably a bit more expensive, but only happens once per template and per compilation.

@honnix
Copy link

honnix commented Sep 8, 2023

@eamonnmcmanus Thank you so much getting this fixed! I'm looking forward to trying in the next release.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants
@cgdecker @honnix @bvolpato @eamonnmcmanus and others