You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@maven.apache.org by "Rainer Reich (Jira)" <ji...@apache.org> on 2020/02/14 18:28:00 UTC

[jira] [Commented] (MNG-6803) ArtifactNotFoundExceptions when building in parallel

    [ https://issues.apache.org/jira/browse/MNG-6803?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17037175#comment-17037175 ] 

Rainer Reich commented on MNG-6803:
-----------------------------------

We think we might have found the problem which is inside the {{org.eclipse.aether.internal.impl.DefaultArtifactResolver#resolve()}} method:

This method first looks into the local repository calling {{lrm.find(...)}} and then downloads the artifacts that are still unresolved in {{performDownloads()}}.
 If after this, the artifacts stored in the results don't have a file set an {{ArtifactNotFoundException}} is thrown.
 (See [https://github.com/apache/maven-resolver/blob/master/maven-resolver-impl/src/main/java/org/eclipse/aether/internal/impl/DefaultArtifactResolver.java#L409])

Now let's say we have two threads A and B that are both entering the {{resolve()}} method and want to resolve the same artifact.
 They could be executed as follows:
 1. A is looking into its local repository and doesn't find the artifact;
 2. B is running and also doesn't find it in its local repository;
 3. B downloads it, finishes the download and marks the item as resolved;
 4. A is continued and doesn't download anything because the item is already resolved;
 5. Then A's result will never have an artifact file set and A runs into the exception.

The simplest fix is to synchronize the whole {{resolve}} method, so that A won't get interrupted.
 Theoretically not optimal, but dead-simple and we could not measure any significant performance impact.
 (See [https://github.com/apache/maven-resolver/pull/42/files])

Another fix (workaround?) we tried, was to look up the artifact in the local repository again after {{performDownloads()}}.
 (See [https://github.com/apache/maven-resolver/pull/41/files])

Both fixes seem to be working. While we managed to set up our workspace so that the original method produced the ArtifactNotFoundException in nearly 50% of the runs,
 the fixed versions never showed any issues.

Probably you will come up with a more sophisticated approach for fixing this problem, but we hope we could help to shed some light on this.

> ArtifactNotFoundExceptions when building in parallel
> ----------------------------------------------------
>
>                 Key: MNG-6803
>                 URL: https://issues.apache.org/jira/browse/MNG-6803
>             Project: Maven
>          Issue Type: Bug
>    Affects Versions: 3.6.2
>            Reporter: Rainer Reich
>            Priority: Major
>         Attachments: maven-debug-log.txt
>
>          Time Spent: 20m
>  Remaining Estimate: 0h
>
> We have a multi-module project with quite many modules and many dependencies and observe pretty random {{ArtifactNotFoundExceptions}} when building in parallel with an empty local repository.
> The "funny" thing is that Maven did in fact download the jar that it complained about not finding.
> In this example Maven said it could not find {{edu.tum.cs:cup-runtime:jar:11a}} (see stacktrace below)
>  But it also said: {{Downloaded from central-mirror: [https://mirror.xy.com/repository/maven-all-mirror/edu/tum/cs/cup-runtime/11a/cup-runtime-11a.jar]}}.
> When looking into the local repository after the failed build we found the cup-runtime.jar in the correct place with the correct checksum.
> We tried the following to "fix" the problem:
>  * build with and without the takari extensions ({{takari-local-repository}} & {{takari-smart-builder}}) using {{--builder smart}}
>  * also build with {{io.takari.aether:aether-connector-okhttp}} extension
>  * only execute goal package instead of install
>  * build with these properties: {{-Daether.connector.basic.threads=1 -Daether.connector.resumeDownloads=false}}
> But nothing helped.
> Unfortunately it seems to be a race condition and we cannot reproduce it consistently but it happens in about 1 out of 5 builds.
> {code:java}
> ...
> [2019-11-18T16:46:29.370Z] [INFO] Downloaded from central-mirror: https://mirror.xy.com/repository/maven-all-mirror/edu/tum/cs/cup-runtime/11a/cup-runtime-11a.jar (13 kB at 738 kB/s)
> ...
> [2019-11-18T16:46:30.894Z] [ERROR] Failed to execute goal on project xy: Could not resolve dependencies for project xy: The following artifacts could not be resolved: edu.tum.cs:cup-runtime:jar:11a, org.checkerframework:checker-qual:jar:2.5.7, org.ow2.asm:asm:jar:7.2, cglib:cglib:jar:3.3.0: Could not find artifact edu.tum.cs:cup-runtime:jar:11a -> [Help 1]
> [2019-11-18T16:46:30.894Z] org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal on project xy: Could not resolve dependencies for project xy: The following artifacts could not be resolved: edu.tum.cs:cup-runtime:jar:11a, org.checkerframework:checker-qual:jar:2.5.7, org.ow2.asm:asm:jar:7.2, cglib:cglib:jar:3.3.0: Could not find artifact edu.tum.cs:cup-runtime:jar:11a
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.getDependencies (LifecycleDependencyResolver.java:269)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.resolveProjectDependencies (LifecycleDependencyResolver.java:147)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.ensureDependenciesAreResolved (MojoExecutor.java:248)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject (SmartBuilderImpl.java:205)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run (SmartBuilderImpl.java:77)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.FutureTask.run (FutureTask.java:264)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
> [2019-11-18T16:46:30.894Z]     at java.lang.Thread.run (Thread.java:834)
> [2019-11-18T16:46:30.894Z] Caused by: org.apache.maven.project.DependencyResolutionException: Could not resolve dependencies for project xy: The following artifacts could not be resolved: edu.tum.cs:cup-runtime:jar:11a, org.checkerframework:checker-qual:jar:2.5.7, org.ow2.asm:asm:jar:7.2, cglib:cglib:jar:3.3.0: Could not find artifact edu.tum.cs:cup-runtime:jar:11a
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.project.DefaultProjectDependenciesResolver.resolve (DefaultProjectDependenciesResolver.java:209)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.getDependencies (LifecycleDependencyResolver.java:243)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.resolveProjectDependencies (LifecycleDependencyResolver.java:147)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.ensureDependenciesAreResolved (MojoExecutor.java:248)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject (SmartBuilderImpl.java:205)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run (SmartBuilderImpl.java:77)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.FutureTask.run (FutureTask.java:264)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
> [2019-11-18T16:46:30.894Z]     at java.lang.Thread.run (Thread.java:834)
> [2019-11-18T16:46:30.894Z] Caused by: org.eclipse.aether.resolution.DependencyResolutionException: The following artifacts could not be resolved: edu.tum.cs:cup-runtime:jar:11a, org.checkerframework:checker-qual:jar:2.5.7, org.ow2.asm:asm:jar:7.2, cglib:cglib:jar:3.3.0: Could not find artifact edu.tum.cs:cup-runtime:jar:11a
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveDependencies (DefaultRepositorySystem.java:357)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.project.DefaultProjectDependenciesResolver.resolve (DefaultProjectDependenciesResolver.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.getDependencies (LifecycleDependencyResolver.java:243)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.resolveProjectDependencies (LifecycleDependencyResolver.java:147)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.ensureDependenciesAreResolved (MojoExecutor.java:248)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject (SmartBuilderImpl.java:205)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run (SmartBuilderImpl.java:77)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.FutureTask.run (FutureTask.java:264)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
> [2019-11-18T16:46:30.894Z]     at java.lang.Thread.run (Thread.java:834)
> [2019-11-18T16:46:30.894Z] Caused by: org.eclipse.aether.resolution.ArtifactResolutionException: The following artifacts could not be resolved: edu.tum.cs:cup-runtime:jar:11a, org.checkerframework:checker-qual:jar:2.5.7, org.ow2.asm:asm:jar:7.2, cglib:cglib:jar:3.3.0: Could not find artifact edu.tum.cs:cup-runtime:jar:11a
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolve (DefaultArtifactResolver.java:424)
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifacts (DefaultArtifactResolver.java:229)
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveDependencies (DefaultRepositorySystem.java:340)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.project.DefaultProjectDependenciesResolver.resolve (DefaultProjectDependenciesResolver.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.getDependencies (LifecycleDependencyResolver.java:243)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.resolveProjectDependencies (LifecycleDependencyResolver.java:147)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.ensureDependenciesAreResolved (MojoExecutor.java:248)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject (SmartBuilderImpl.java:205)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run (SmartBuilderImpl.java:77)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.FutureTask.run (FutureTask.java:264)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
> [2019-11-18T16:46:30.894Z]     at java.lang.Thread.run (Thread.java:834)
> [2019-11-18T16:46:30.894Z] Caused by: org.eclipse.aether.transfer.ArtifactNotFoundException: Could not find artifact edu.tum.cs:cup-runtime:jar:11a
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolve (DefaultArtifactResolver.java:414)
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifacts (DefaultArtifactResolver.java:229)
> [2019-11-18T16:46:30.894Z]     at org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveDependencies (DefaultRepositorySystem.java:340)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.project.DefaultProjectDependenciesResolver.resolve (DefaultProjectDependenciesResolver.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.getDependencies (LifecycleDependencyResolver.java:243)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleDependencyResolver.resolveProjectDependencies (LifecycleDependencyResolver.java:147)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.ensureDependenciesAreResolved (MojoExecutor.java:248)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:202)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
> [2019-11-18T16:46:30.894Z]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject (SmartBuilderImpl.java:205)
> [2019-11-18T16:46:30.894Z]     at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run (SmartBuilderImpl.java:77)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.FutureTask.run (FutureTask.java:264)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
> [2019-11-18T16:46:30.894Z]     at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
> [2019-11-18T16:46:30.894Z]     at java.lang.Thread.run (Thread.java:834)
> {code}



--
This message was sent by Atlassian Jira
(v8.3.4#803005)