[MRESOLVER-134] Unsatisfiable Range header causing 416 HTTP error

[jira-importer]

Dmitriy Panov opened MRESOLVER-134 and commented

How to reproduce

Put partially downloaded artifacts from attachment (corrupted probably due to MNG-4706 and MRESOLVER-25) into ~/.m2/repository and try to resolve org.junit.jupiter:junit-jupiter-api:5.0.0

Expected outcome

Artifacts are resolved

Actual outcome

Caused by: org.eclipse.aether.transfer.ArtifactTransferException: Could not transfer artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0 from/to central (https://repo1.maven.org/maven2/): status code: 416, reason phrase: Range Not Satisfiable (416)Caused by: org.eclipse.aether.transfer.ArtifactTransferException: Could not transfer artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0 from/to central (https://repo1.maven.org/maven2/): status code: 416, reason phrase: Range Not Satisfiable (416) at org.eclipse.aether.connector.basic.ArtifactTransportListener.transferFailed(ArtifactTransportListener.java:52) at org.eclipse.aether.connector.basic.BasicRepositoryConnector$TaskRunner.run(BasicRepositoryConnector.java:369) at org.eclipse.aether.util.concurrency.RunnableErrorForwarder$1.run(RunnableErrorForwarder.java:75) at org.eclipse.aether.connector.basic.BasicRepositoryConnector$DirectExecutor.execute(BasicRepositoryConnector.java:628) at org.eclipse.aether.connector.basic.BasicRepositoryConnector.get(BasicRepositoryConnector.java:262) at org.eclipse.aether.internal.impl.DefaultArtifactResolver.performDownloads(DefaultArtifactResolver.java:499) at org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolve(DefaultArtifactResolver.java:400) ... 31 more

Workaround

Pass -Daether.connector.resumeDownloads=false

 

Issue is still present in 1.5.0

---

Affects: 1.3.3

Attachments:

• broken_m2.zip (145.95 kB)

Issue Links:

• MNG-4706 Multithreaded building can create bad files for downloaded artifacts in local repository
  ("is caused by")
• MRESOLVER-25 Resume support is broken under high concurrency
  ("is caused by")

Remote Links:

• GitHub Pull Request #165
  

[jira-importer]

Michael Osipov commented

Will have a look

[jira-importer]

Michael Osipov commented

Do you think you could provide a debug log with HttpClient header log enabled?

[jira-importer]

Dmitriy Panov commented

Could you please advise how to do that properly?

Here is an easy way to reproduce the problem  DmPanov@a4e8bdf

[jira-importer]

Michael Osipov commented

Read here: https://issues.apache.org/jira/browse/WAGON-590?focusedCommentId=17095247&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-17095247

[jira-importer]

Dmitriy Panov commented

Specified following system properties for ResolveArtifacts.main, still no additional logging:
-Dorg.slf4j.simpleLogger.log.org.apache.maven.wagon.providers.http.httpclient=DEBUG
-Dorg.slf4j.simpleLogger.log.org.apache.maven.wagon.providers.http.httpclient.wire=ERROR
-Dorg.slf4j.simpleLogger.log.org.apache.http=DEBUG
-Dorg.slf4j.simpleLogger.log.org.apache.http.wire=ERROR

[jira-importer]

Michael Osipov commented

So you are not using through Maven? If not set up logging correctly and try again.

[jira-importer]

Dmitriy Panov commented

Please check out this link DmPanov@a4e8bdf
Just running ResolveArtifacts.main reproduces the problem

[jira-importer]

Michael Osipov commented

I was able to reproduce this issue. looking through...

[jira-importer]

Michael Osipov commented

The behavior is correct. The JAR file has 75994 bytes. Byte range requests start with zero. You open range is off by one. The behavior does reject your reject.
This is how it should be:

$ truncate -s -1 ./maven-resolver-demos/maven-resolver-demo-snippets/src/main/resources/junit-jupiter-api-5.0.0.jar.part
osipovmi@deblndw011x:~/var/Projekte/DmPanov ((a4e8bdf7...) *)
$ find . -name \*.part -exec ls -l {} +
-rw-r--r--  1 osipovmi  cad  75993 28 Aug. 21:40 ./maven-resolver-demos/maven-resolver-demo-snippets/src/main/resources/junit-jupiter-api-5.0.0.jar.part
-rw-r--r--  1 osipovmi  cad  75993 28 Aug. 21:39 ./maven-resolver-demos/maven-resolver-demo-snippets/target/classes/junit-jupiter-api-5.0.0.jar.part
-rw-r--r--  1 osipovmi  cad  75994 28 Aug. 21:39 ./target/local-repo/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar.part
osipovmi@deblndw011x:~/var/Projekte/DmPanov ((a4e8bdf7...) *)
$ mvn exec:java -pl maven-resolver-demos/maven-resolver-demo-snippets -Dexec.mainClass=org.apache.maven.resolver.examples.ResolveArtifact -Dorg.slf4j.simpleLogger.log.org.apache.http=DEBUG -Dorg.slf4j.simpleLogger.log.org.apache.http.wire=ERROR
[INFO] Scanning for projects...
[WARNING] The POM for org.eclipse.m2e:lifecycle-mapping:jar:1.0.0 is missing, no dependency information available
[WARNING] Failed to retrieve plugin descriptor for org.eclipse.m2e:lifecycle-mapping:1.0.0: Plugin org.eclipse.m2e:lifecycle-mapping:1.0.0 or one of its dependencies could not be resolved: Failure to find org.eclipse.m2e:lifecycle-mapping:jar:1.0.0 in https://deblndw011x.ad001.siemens.net/nexus/content/groups/dynamowerk-public was cached in the local repository, resolution will not be reattempted until the update interval of nexus-dynamowerk-berlin has elapsed or updates are forced
[INFO]
[INFO] -------< org.apache.maven.resolver:maven-resolver-demo-snippets >-------
[INFO] Building Maven Artifact Resolver Demo Snippets 1.3.3
[INFO] --------------------------------[ jar ]---------------------------------
[WARNING] The POM for org.eclipse.m2e:lifecycle-mapping:jar:1.0.0 is missing, no dependency information available
[WARNING] Failed to retrieve plugin descriptor for org.eclipse.m2e:lifecycle-mapping:1.0.0: Plugin org.eclipse.m2e:lifecycle-mapping:1.0.0 or one of its dependencies could not be resolved: Failure to find org.eclipse.m2e:lifecycle-mapping:jar:1.0.0 in https://deblndw011x.ad001.siemens.net/nexus/content/groups/dynamowerk-public was cached in the local repository, resolution will not be reattempted until the update interval of nexus-dynamowerk-berlin has elapsed or updates are forced
[INFO]
[INFO] --- exec-maven-plugin:3.0.0:java (default-cli) @ maven-resolver-demo-snippets ---
------------------------------------------------------------
ResolveArtifact
Resolving artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0
Downloading artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0 from central (https://repo.maven.apache.org/maven2/, default, releases+snapshots)
Downloading: https://repo.maven.apache.org/maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection request: [route: {s}->https://repo.maven.apache.org:443][total kept alive: 0; route allocated: 0 of 50; total allocated: 0 of 100]
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection leased: [id: 0][route: {s}->https://repo.maven.apache.org:443][total kept alive: 0; route allocated: 1 of 50; total allocated: 1 of 100]
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator - Connecting to repo.maven.apache.org:443
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestTargetAuthentication - Target auth state: UNCHALLENGED
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.client.DefaultHttpClient - Attempt 1 to execute request
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Sending request: GET /maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar HTTP/1.1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> GET /maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar HTTP/1.1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Cache-Control: no-cache, no-store
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Pragma: no-cache
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Range: bytes=75993-
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> If-Unmodified-Since: Fri, 28 Aug 2020 19:40:10 GMT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Accept-Encoding: identity
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Host: repo.maven.apache.org
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Connection: Keep-Alive
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> User-Agent: Aether
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Receiving response: HTTP/1.1 206 Partial Content
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << HTTP/1.1 206 Partial Content
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Connection: keep-alive
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Content-Length: 1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << ETag: "59468e20e8d8c03c17bd089659d26654"
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Content-Type: application/java-archive
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Last-Modified: Sun, 10 Sep 2017 18:08:32 GMT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Checksum-MD5: 59468e20e8d8c03c17bd089659d26654
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Checksum-SHA1: 0f7fe1b74bef74d640493781abecafba191472ad
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Via: 1.1 varnish
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Accept-Ranges: bytes
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Date: Fri, 28 Aug 2020 19:41:11 GMT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Via: 1.1 varnish
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Age: 4963801
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Served-By: cache-bwi5146-BWI, cache-hhn4041-HHN
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Cache: HIT, HIT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Cache-Hits: 1, 2
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Timer: S1598643672.719714,VS0,VE0
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Content-Range: bytes 75993-75993/75994
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.client.DefaultHttpClient - Connection can be kept alive indefinitely
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection [id: 0][route: {s}->https://repo.maven.apache.org:443] can be kept alive indefinitely
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection released: [id: 0][route: {s}->https://repo.maven.apache.org:443][total kept alive: 1; route allocated: 1 of 50; total allocated: 1 of 100]
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection request: [route: {s}->https://repo.maven.apache.org:443][total kept alive: 1; route allocated: 1 of 50; total allocated: 1 of 100]
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection leased: [id: 0][route: {s}->https://repo.maven.apache.org:443][total kept alive: 0; route allocated: 1 of 50; total allocated: 1 of 100]
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.client.DefaultHttpClient - Stale connection check
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestTargetAuthentication - Target auth state: UNCHALLENGED
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.client.protocol.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.client.DefaultHttpClient - Attempt 1 to execute request
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Sending request: GET /maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar.sha1 HTTP/1.1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> GET /maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar.sha1 HTTP/1.1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Cache-Control: no-cache, no-store
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Pragma: no-cache
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Accept-Encoding: gzip,deflate
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Host: repo.maven.apache.org
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> Connection: Keep-Alive
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - >> User-Agent: Aether
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << HTTP/1.1 200 OK
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Connection: keep-alive
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Content-Length: 40
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << ETag: "48b39b3d5c288ffb14ad9b35f63bcf59"
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Content-Type: text/plain
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Last-Modified: Sun, 10 Sep 2017 18:08:32 GMT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Checksum-MD5: 48b39b3d5c288ffb14ad9b35f63bcf59
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Checksum-SHA1: 6069507a1940c5ceb4865fe9dc834fac11aaf62f
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Via: 1.1 varnish
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Accept-Ranges: bytes
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Date: Fri, 28 Aug 2020 19:41:11 GMT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Via: 1.1 varnish
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << Age: 7215890
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Served-By: cache-iad2132-IAD, cache-hhn4041-HHN
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Cache: HIT, HIT
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Cache-Hits: 1, 1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.headers - << X-Timer: S1598643672.789877,VS0,VE1
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.client.DefaultHttpClient - Connection can be kept alive indefinitely
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection [id: 0][route: {s}->https://repo.maven.apache.org:443] can be kept alive indefinitely
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection released: [id: 0][route: {s}->https://repo.maven.apache.org:443][total kept alive: 1; route allocated: 1 of 50; total allocated: 1 of 100]
Downloaded: https://repo.maven.apache.org/maven2/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar (75 KB at 0.0 KB/sec)
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection manager is shutting down
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:52078<->151.101.112.215:443 closed
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:52078<->151.101.112.215:443 closed
[org.apache.maven.resolver.examples.ResolveArtifact.main()] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection manager shut down
Downloaded artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0 from central (https://repo.maven.apache.org/maven2/, default, releases+snapshots)
Resolved artifact org.junit.jupiter:junit-jupiter-api:jar:5.0.0 from central (https://repo.maven.apache.org/maven2/, default, releases+snapshots)
org.junit.jupiter:junit-jupiter-api:jar:5.0.0 resolved to  /var/osipovmi/Projekte/DmPanov/target/local-repo/org/junit/jupiter/junit-jupiter-api/5.0.0/junit-jupiter-api-5.0.0.jar
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 12.417 s
[INFO] Finished at: 2020-08-28T21:41:11+02:00
[INFO] ------------------------------------------------------------------------

[jira-importer]

Michael Osipov commented

Here is the code:

    /**
     * Gets the byte offset within the resource from which the download should resume if supported.
     *
     * @return The zero-based index of the first byte to download or {@code 0} for a full download from the start of the
     *         resource, never negative.
     */
    public long getResumeOffset()
    {
        if ( resume )
        {
            if ( dataFile != null )
            {
                return dataFile.length();
            }
            if ( dataBytes != null )
            {
                return dataBytes.size();
            }
        }
        return 0;
    }

So if the file is partial 0 to size-1 has been downloaded already. It will start with size. The behavior you see is not a problem with resume, but with the lacking synchronization (race condition). Maven Resolver 1.6.0 wil provide two synchronization contexts which solve this issue.