Comment 1 Alexander Kurtakov 2021-12-14 06:01:22 EST

Is update actually failing?

Comment 2 Andrey Loskutov 2021-12-14 06:30:45 EST

(In reply to Alexander Kurtakov from comment #1)
> Is update actually failing?

No, everything seem to be installed without further errors.

Comment 3 Alexander Kurtakov 2021-12-14 06:44:37 EST

Can you please identify which server/update site causes it? I monitor error log and install a lot of plugins and haven't experienced it.

Comment 4 Andrey Loskutov 2021-12-14 07:24:29 EST

(In reply to Alexander Kurtakov from comment #3)
> Can you please identify which server/update site causes it? I monitor error
> log and install a lot of plugins and haven't experienced it.

I install everything by importing plugins via this file:
eclipse.platform.ui/releng/org.eclipse.ui.releng/platformUiTools.p2f

Just tried again, it throws now two errors - one with different stack. I assume they are timing related. Not sure if this is just co-incidently or not - every time the error is logged after this warning:

Server returned lastModified <= 0 for https://raw.githubusercontent.com/iloveeclipse/plugins/latest/content.xml

So could it be, github servers are "special" in some way. However, that worked before without any errors.


eclipse.buildId=4.23.0.I20211213-1800
java.version=11.0.10
java.vendor=Red Hat, Inc.
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Command-line arguments:  -os linux -ws gtk -arch x86_64

org.eclipse.ecf.provider.filetransfer.httpclient5
Error
Tue Dec 14 13:20:12 CET 2021
org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 552424; received: 282167);children=[]]

org.apache.hc.core5.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 552424; received: 282167)
	at org.apache.hc.core5.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:175)
	at org.apache.hc.core5.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:195)
	at org.apache.hc.core5.http.impl.io.ContentLengthInputStream.close(ContentLengthInputStream.java:101)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:111)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:197)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.cancel(HttpClientRetrieveFileTransfer.java:174)
	at org.eclipse.equinox.internal.p2.transport.ecf.FileReader.handleTransferEvent(FileReader.java:229)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer.fireTransferReceiveDataEvent(AbstractRetrieveFileTransfer.java:392)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.fireTransferReceiveDataEvent(HttpClientRetrieveFileTransfer.java:1030)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer.handleReceivedData(AbstractRetrieveFileTransfer.java:296)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:181)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

Comment 5 Andrey Loskutov 2021-12-14 07:29:58 EST

Scott: any ideas?

Steps to reproduce for me:

Download and start SDK nightly build.
I use -Declipse.p2.unsignedPolicy=allow in eclipse.ini to avoid dialogs.
File -> Import -> Install Software from File -> 
select eclipse.platform.ui/releng/org.eclipse.ui.releng/platformUiTools.p2f
select all
Proceed.
Random org.apache.hc.core5.http errors reported in the Error log.

Comment 6 Ed Merks 2022-02-10 08:54:10 EST

I haven't seen anything like this  and just now I tried in a self hosted launch to follow these steps and there were no such exceptions.  Likely this was a server problem at that time.

Comment 7 Andrey Loskutov 2022-02-10 08:57:13 EST

(In reply to Ed Merks from comment #6)
> I haven't seen anything like this  and just now I tried in a self hosted
> launch to follow these steps and there were no such exceptions.  Likely this
> was a server problem at that time.

I see it every day on installing bundles in nightly SDK.

Here log from today:

eclipse.buildId=4.23.0.I20220209-1800
java.version=11.0.10
java.vendor=Red Hat, Inc.
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Command-line arguments:  -os linux -ws gtk -arch x86_64

org.eclipse.ecf.provider.filetransfer.httpclient5
Error
Thu Feb 10 08:42:34 CET 2022
org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected;children=[]]

org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:263)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:222)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:147)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:314)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:112)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:198)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:199)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

Comment 8 Ed Merks 2022-02-10 08:59:48 EST

Are you able to reproduce it in a self-hosted launch to identify the server involved?  I set a breakpoint where the exception was thrown and it's never hit.  It definitely won't be solved it if can't be reproduced.  It really looks to me like a network problem...  It might depend on what mirror is accessed.  We'd need the URL...

Comment 9 Andrey Loskutov 2022-02-10 09:05:06 EST

(In reply to Ed Merks from comment #8)
> Are you able to reproduce it in a self-hosted launch to identify the server
> involved?  I set a breakpoint where the exception was thrown and it's never
> hit.  It definitely won't be solved it if can't be reproduced.  It really
> looks to me like a network problem...  It might depend on what mirror is
> accessed.  We'd need the URL...

Ed, I just do this procedure every day:
https://wiki.eclipse.org/Platform/How_to_Contribute#.5B2.5D_Install_the_development_tools

It always worked since years till http5 was added and I've immediately saw the regression, it is part of my morning routine to do that install.

I assume some of the update sites listed here could run servers that are "different" in the http implementation, so the new client sees something that surprises it and didn't surprised the old one: 

http://git.eclipse.org/c/platform/eclipse.platform.ui.git/plain/releng/org.eclipse.ui.releng/platformUiTools.p2f

Comment 10 Ed Merks 2022-02-10 10:11:25 EST

Created attachment 288025 [details]
The log following the steps

Even following those steps, I cannot reproduce the problem.  Nothing like that in the log.

I still get the sense this is a network problem.  It seems highly unlikely that the problem is one that doesn't happen on Windows but only on Linux.

It would be good to know the URLs involved but we'll only know that if you reproduce it in a self-host launch setting a breakpoint...

Comment 11 Andrey Loskutov 2022-02-10 10:27:05 EST

(In reply to Ed Merks from comment #10)
> Created attachment 288025 [details]
> The log following the steps
> 
> Even following those steps, I cannot reproduce the problem.  Nothing like
> that in the log.

Note, you use very old 4.22 build, I use latest 4.23.

> I still get the sense this is a network problem.  It seems highly unlikely
> that the problem is one that doesn't happen on Windows but only on Linux.

Here is the log from Windows / completely different network (my notebook on my home DSL connection vs my office before).

eclipse.buildId=4.23.0.I20220205-1800
java.version=11.0.8
java.vendor=Oracle Corporation
BootLoader constants: OS=win32, ARCH=x86_64, WS=win32, NL=de_DE
Command-line arguments:  -os win32 -ws win32 -arch x86_64

org.eclipse.ecf.provider.filetransfer.httpclient5
Error
Sun Feb 06 09:16:44 CET 2022
org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected;children=[]]

org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:263)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:222)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:147)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:314)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:112)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:198)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:199)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

> It would be good to know the URLs involved but we'll only know that if you
> reproduce it in a self-host launch setting a breakpoint...

We should report bug for ecf. One shouldn't need a debugger to get matching to the error message.

Comment 12 Andrey Loskutov 2022-02-10 10:31:46 EST

(In reply to Andrey Loskutov from comment #11)
> We should report bug for ecf. One shouldn't need a debugger to get matching
> to the error message.

Reported bug 578678

Comment 13 Ed Merks 2022-02-10 11:17:04 EST

I keep mentioning a debugger because we don't know the URL and it might well be that you get different mirrors than I do here.  We really can't rule out a problem with the network or with some particular server.  And given you have an Eclipse installation, launching a self-hosted IDE and repeating the steps there is not hard...

Comment 14 Andrey Loskutov 2022-02-10 11:28:57 EST

I see one exception in debugger on fetching this file below.

!ENTRY org.eclipse.ecf.provider.filetransfer.httpclient5 4 0 2022-02-10 17:26:00.881
!MESSAGE org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected;children=[]]
!STACK 0
org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:263)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:222)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:147)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:314)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:112)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:198)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:199)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)



FileTransferID[ecf.provider.filetransfer:https://www.yourkit.com/download/yjp2021_11_for_eclipse/site.xml]

Socket[addr=www.yourkit.com/104.21.63.154,port=443,localport=47320]

java.nio.HeapByteBuffer[pos=1369 lim=1369 cap=4096]

org.apache.hc.core5.http.config.Http1Config [bufferSize=8192, chunkSizeHint=-1, waitForContinueTimeout=3 SECONDS, maxLineLength=-1, maxHeaderCount=-1, maxEmptyLineCount=10, initialWindowSize=65535]

org.apache.hc.core5.http.impl.io.IncomingHttpEntity [Content-Type: application/xml,Content-Encoding: gzip,Chunked: true]

org.apache.hc.client5.http.classic.methods.HttpGet
GET /download/yjp2021_11_for_eclipse/site.xml

org.apache.hc.client5.http.impl.classic.CloseableHttpResponse
200 OK HTTP/1.1

org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer.responseHeaders
{Transfer-Encoding=chunked, Server=cloudflare, CF-RAY=6db69781cd36cc7f-WAW, x-frame-options=SAMEORIGIN, Connection=keep-alive, Date=Thu, 10 Feb 2022 16:07:41 GMT, strict-transport-security=max-age=31536000; includeSubDomains; preload, last-modified=Sun, 06 Feb 2022 18:50:01 GMT, CF-Cache-Status=DYNAMIC, Cache-Control=public, must-revalidate, proxy-revalidate, max-age=604800, s-maxage=604800, x-xss-protection=1; mode=block, x-content-type-options=nosniff, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=8xVt5QYP5IcecwTToZE%2FiqJlwSpT%2FQfFrfLsBvDz3C5IattBMPrZD8RRzYOY9BTfYGJr8aUHDMaft4cyjjJv5Ov5f75e7l18rgx9ACsHrnEPPyGD97cpcAKUyroGdYDFw2w%3D"}],"group":"cf-nel","max_age":604800}, etag=W/"595-1644173401057", alt-svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400, Content-Type=application/xml, Expect-CT=max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"}

Comment 15 Andrey Loskutov 2022-02-10 11:50:18 EST

(In reply to Andrey Loskutov from comment #14)
> I see one exception in debugger on fetching this file below.
> 
> FileTransferID[ecf.provider.filetransfer:https://www.yourkit.com/download/
> yjp2021_11_for_eclipse/site.xml]

On second debug attempt also exception on same file.

Comment 16 Ed Merks 2022-02-10 23:47:52 EST

In my Oomph development environment, visiting this site in the repository explorer

https://www.yourkit.com/download/yjp2021_11_for_eclipse/site.xml

produces this stack trace:

!ENTRY org.eclipse.ecf.provider.filetransfer.httpclient5 4 0 2022-02-11 05:33:52.130
!MESSAGE org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.MalformedChunkCodingException: CRLF expected at end of chunk;children=[]]
!STACK 0
org.apache.hc.core5.http.MalformedChunkCodingException: CRLF expected at end of chunk
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:250)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:222)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:147)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:314)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:112)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:198)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:199)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

A slightly different error but also one suggesting the content is truncated.

Also this one:

!ENTRY org.eclipse.ecf.provider.filetransfer.httpclient5 4 0 2022-02-11 05:39:09.599
!MESSAGE org.eclipse.core.runtime.Status[plugin=org.eclipse.ecf.provider.filetransfer.httpclient5;code=4;message=hardClose;severity4;exception=org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected;children=[]]
!STACK 0
org.apache.hc.core5.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:263)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:222)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:147)
	at org.apache.hc.core5.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:314)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.impl.io.IncomingHttpEntity.close(IncomingHttpEntity.java:112)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.http.io.entity.HttpEntityWrapper.close(HttpEntityWrapper.java:120)
	at org.apache.hc.core5.io.Closer.close(Closer.java:48)
	at org.apache.hc.core5.http.message.BasicClassicHttpResponse.close(BasicClassicHttpResponse.java:93)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpResponse.close(CloseableHttpResponse.java:200)
	at org.eclipse.ecf.provider.filetransfer.httpclient5.HttpClientRetrieveFileTransfer.hardClose(HttpClientRetrieveFileTransfer.java:198)
	at org.eclipse.ecf.provider.filetransfer.retrieve.AbstractRetrieveFileTransfer$1.performFileTransfer(AbstractRetrieveFileTransfer.java:199)
	at org.eclipse.ecf.filetransfer.FileTransferJob.run(FileTransferJob.java:76)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

It's quite easily reproducible for that specific site, so it is indeed good to know the URL!!

I don't believe this is a p2 bug.  There's no sign of p2 on this stack after all...

I'm not even convinced there is a bug.  Some sites are ill behaved.  For example, the https://git.eclipse.org/c site regularly serves up content with trailing bytes that makes the XML invalid:

https://git.eclipse.org/c/oomph/org.eclipse.oomph.git/plain/setups/Oomph.setup

The quality is so poor that in our set archiver, we always download the bytes twice and check if the bytes the same twice before using them...

Comment 17 Andrey Loskutov 2022-02-11 06:54:08 EST

I've just tested with 4.22 (http4 client) - no errors at all. So either http5 client is now more verbose or has some issues with the sites where http4 was OK.

Moving to ecf.