Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.
Bug 545920 - Cloning fails with 'Pipe closed after 0 cycles' when using Apache MINA sshd
Summary: Cloning fails with 'Pipe closed after 0 cycles' when using Apache MINA sshd
Status: RESOLVED FIXED
Alias: None
Product: JGit
Classification: Technology
Component: JGit (show other bugs)
Version: 5.3   Edit
Hardware: PC Windows 10
: P3 normal (vote)
Target Milestone: 5.2.2   Edit
Assignee: Project Inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-29 06:33 EDT by Holger Voormann CLA
Modified: 2019-05-17 10:40 EDT (History)
6 users (show)

See Also:


Attachments
jgit53 stderr excerpt with start and error only (11.23 KB, application/octet-stream)
2019-04-01 06:42 EDT, Harald Hermann CLA
no flags Details
jgit53 stdout log file (29 bytes, application/octet-stream)
2019-04-01 06:42 EDT, Harald Hermann CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Holger Voormann CLA 2019-03-29 06:33:55 EDT
The cloning of a Git repository from an Atlassian Bitbucket v5.2.1 server via the "ssh://..." protocol fails after some time when using "Apache MINA sshd" as SSH client in the Eclipse IDE. The clone command starts without problems, but after some time an error dialog appears with the message "Pipe closed after 0 cycles". When using "JSch" instead of "Apache MINA sshd" the repository can be cloned without problems. The cloning of other Git repositories from the same server using "Apache MINA sshd" works, only one specific repository can not be cloned using "Apache MINA sshd".

Unfortunately, I cannot share the repository because it is from a customer. The Git repository is about 1.1 GB in size, contains thousands of files, long path names with special characters, 17 branches, but no tags. The issue has been reproduced on different computers. But the issue did not occur with a sample repository containing long path names with special characters.

The following stack trace has been logged:

!ENTRY org.eclipse.egit.ui 4 0 2019-03-28 16:33:19.419
!MESSAGE Pipe closed after 0 cycles
!STACK 0
org.eclipse.jgit.api.errors.TransportException: Pipe closed after 0 cycles
	at org.eclipse.jgit.api.FetchCommand.call(FetchCommand.java:255)
	at org.eclipse.jgit.api.CloneCommand.fetch(CloneCommand.java:302)
	at org.eclipse.jgit.api.CloneCommand.call(CloneCommand.java:200)
	at org.eclipse.egit.core.op.CloneOperation.run(CloneOperation.java:180)
	at org.eclipse.egit.ui.internal.clone.AbstractGitCloneWizard.executeCloneOperation(AbstractGitCloneWizard.java:486)
	at org.eclipse.egit.ui.internal.clone.AbstractGitCloneWizard.access$2(AbstractGitCloneWizard.java:479)
	at org.eclipse.egit.ui.internal.clone.AbstractGitCloneWizard$6.run(AbstractGitCloneWizard.java:458)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: org.eclipse.jgit.errors.TransportException: Pipe closed after 0 cycles
	at org.eclipse.jgit.transport.BasePackFetchConnection.doFetch(BasePackFetchConnection.java:400)
	at org.eclipse.jgit.transport.BasePackFetchConnection.fetch(BasePackFetchConnection.java:323)
	at org.eclipse.jgit.transport.BasePackFetchConnection.fetch(BasePackFetchConnection.java:314)
	at org.eclipse.jgit.transport.FetchProcess.fetchObjects(FetchProcess.java:265)
	at org.eclipse.jgit.transport.FetchProcess.executeImp(FetchProcess.java:163)
	at org.eclipse.jgit.transport.FetchProcess.execute(FetchProcess.java:124)
	at org.eclipse.jgit.transport.Transport.fetch(Transport.java:1271)
	at org.eclipse.jgit.api.FetchCommand.call(FetchCommand.java:244)
	... 7 more
Caused by: java.io.IOException: Pipe closed after 0 cycles
	at org.apache.sshd.common.channel.ChannelPipedInputStream.read(ChannelPipedInputStream.java:121)
	at java.io.FilterInputStream.read(FilterInputStream.java:133)
	at org.eclipse.jgit.util.io.TimeoutInputStream.read(TimeoutInputStream.java:123)
	at org.eclipse.jgit.transport.SideBandInputStream.read(SideBandInputStream.java:142)
	at org.eclipse.jgit.transport.PackParser.fill(PackParser.java:1261)
	at org.eclipse.jgit.transport.PackParser$InflaterStream.read(PackParser.java:1817)
	at java.io.InputStream.read(InputStream.java:101)
	at org.eclipse.jgit.transport.PackParser.whole(PackParser.java:1089)
	at org.eclipse.jgit.transport.PackParser.indexOneObject(PackParser.java:1013)
	at org.eclipse.jgit.transport.PackParser.parse(PackParser.java:568)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectoryPackParser.parse(ObjectDirectoryPackParser.java:197)
	at org.eclipse.jgit.transport.PackParser.parse(PackParser.java:529)
	at org.eclipse.jgit.transport.BasePackFetchConnection.receivePack(BasePackFetchConnection.java:823)
	at org.eclipse.jgit.transport.BasePackFetchConnection.doFetch(BasePackFetchConnection.java:393)
	... 14 more
	Suppressed: java.io.IOException: Pipe closed after 0 cycles
		at org.apache.sshd.common.channel.ChannelPipedInputStream.read(ChannelPipedInputStream.java:121)
		at java.io.FilterInputStream.read(FilterInputStream.java:133)
		at org.eclipse.jgit.util.io.TimeoutInputStream.read(TimeoutInputStream.java:123)
		at org.eclipse.jgit.transport.SideBandInputStream.read(SideBandInputStream.java:142)
		at org.eclipse.jgit.transport.PackParser.fill(PackParser.java:1261)
		at org.eclipse.jgit.transport.PackParser$InflaterStream.read(PackParser.java:1817)
		at java.io.InputStream.read(InputStream.java:101)
		at org.eclipse.jgit.transport.PackParser$InflaterStream.close(PackParser.java:1839)
		at org.eclipse.jgit.transport.PackParser.whole(PackParser.java:1096)
		... 20 more
Comment 1 Thomas Wolf CLA 2019-03-29 07:47:52 EDT
No idea except: could it be that you're running into a timeout? Try to increase the "connection timeout" in the git preferences.
Comment 2 Holger Voormann CLA 2019-03-29 08:43:46 EDT
(In reply to Thomas Wolf from comment #1)
> No idea except: could it be that you're running into a timeout? Try to
> increase the "connection timeout" in the git preferences.

Even if in "Window > Preferences: Team > Git" the "Connection timeout (seconds)" is set to 9999 (instead of 30), the error dialog appears after a few minutes.
Comment 3 Thomas Wolf CLA 2019-03-29 11:12:23 EDT
(In reply to Holger Voormann from comment #2)
> (In reply to Thomas Wolf from comment #1)
> > No idea except: could it be that you're running into a timeout? Try to
> > increase the "connection timeout" in the git preferences.
> 
> Even if in "Window > Preferences: Team > Git" the "Connection timeout
> (seconds)" is set to 9999 (instead of 30), the error dialog appears after a
> few minutes.

So not a timeout problem.

Analyzing this might be easier using the command-line JGit (option "--ssh apache" without the double quotes to make it used the Apache MINA sshd SSH client). Perhaps with full debug logging enabled.
Comment 4 Holger Voormann CLA 2019-03-29 12:18:04 EDT
(In reply to Thomas Wolf from comment #3)
> ...
> Analyzing this might be easier using the command-line JGit (option "--ssh
> apache" without the double quotes to make it used the Apache MINA sshd SSH
> client). Perhaps with full debug logging enabled.

I don't know how to do that. Could you direct me to an instruction? I've already used JGit in a Java application, but not yet the command-line JGit.
Comment 5 Thomas Wolf CLA 2019-03-29 13:22:19 EDT
(In reply to Holger Voormann from comment #4)
> (In reply to Thomas Wolf from comment #3)
> > ...
> > Analyzing this might be easier using the command-line JGit (option "--ssh
> > apache" without the double quotes to make it used the Apache MINA sshd SSH
> > client). Perhaps with full debug logging enabled.
> 
> I don't know how to do that. Could you direct me to an instruction? I've
> already used JGit in a Java application, but not yet the command-line JGit.

1. Download the command-line jgit from https://www.eclipse.org/jgit/download/
   (direct link: https://repo.eclipse.org/content/groups/releases//org/eclipse/jgit/org.eclipse.jgit.pgm/5.3.0.201903130848-r/org.eclipse.jgit.pgm-5.3.0.201903130848-r.sh )

2. Move to an appropriate place and rename it to something manageable, like
   jgit53. Make sure it's executable.

3. Create a file log4j.debug somewhere with the following contents:

  log4j.rootLogger=DEBUG, stderr

  log4j.appender.stderr=org.apache.log4j.ConsoleAppender
  log4j.appender.stderr.Target=System.err
  log4j.appender.stderr.layout=org.apache.log4j.PatternLayout
  log4j.appender.stderr.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

The following steps are on Mac OS: basically define the environment variable _JAVA_OPTIONS to point log4j to that file, then run jgit53. I have my log4j.debug file in my home directory:

4. Execute

  export _JAVA_OPTIONS='-Dlog4j.configuration=file:///Users/thomas/log4j.debug'
  jgit53 clone ssh://wherever.example.org/whatever --ssh apache

This might produce lots of debug logging. Possibly redirect stderr to a file for this.

If the problem re-occurs, attach the log to this bug report.

Don't forget to re-set _JAVA_OPTIONS afterwards, otherwise other Java programs might pick up the environment variable and also produce lots of log output.
Comment 6 Harald Hermann CLA 2019-04-01 06:42:17 EDT
Created attachment 278096 [details]
jgit53 stderr excerpt with start and error only
Comment 7 Harald Hermann CLA 2019-04-01 06:42:53 EDT
Created attachment 278097 [details]
jgit53 stdout log file
Comment 8 Harald Hermann CLA 2019-04-01 06:45:46 EDT
I have executed


export _JAVA_OPTIONS='-Dlog4j.configuration=file:///home/hhermann/temp/eclipse_bug_545920/log4j.debug'
./jgit53.sh clone ssh://socgit.advantest.com:7999/doc/v93000-doc.git --ssh apache >> jgit53.log 2>> jgit53_error.log


and attached the log files here.

The original jgit53_error.log is 53MB and could not be uploaded here so I removed the middle part.
Comment 9 Thomas Wolf CLA 2019-04-01 07:11:02 EDT
(In reply to Harald Hermann from comment #8)
> The original jgit53_error.log is 53MB and could not be uploaded here so I
> removed the middle part.

From jgit53_error.log:

Receiving objects:       33% ( 57307/173010)
2019-04-01 11:41:18 DEBUG AbstractChannel$GracefulChannelCloseable:620 - close(ChannelExec[id=0, recipient=0]-JGitClientSession[hhermann@socgit.advantest.com/10.206.117.25:7999])[immediately=true] processing

So something is closing down the connection in the middle of the clone.
Could I get the part of this log from the previous "Receiving objects" line? We'll need to figure why some code closes down the connection.
Comment 10 Thomas Wolf CLA 2019-04-01 07:14:48 EDT
(In reply to Harald Hermann from comment #8)
> I have executed
> 
> export
> _JAVA_OPTIONS='-Dlog4j.configuration=file:///home/hhermann/temp/
> eclipse_bug_545920/log4j.debug'
> ./jgit53.sh clone ssh://socgit.advantest.com:7999/doc/v93000-doc.git --ssh
> apache >> jgit53.log 2>> jgit53_error.log

It looks as if you're on Linux. So probably not a Windows-specific problem.

But it this the same problem that Holger reported? He reported "Pipe closed after 0 cycles", you got "Packfile is truncated". Of course it's possible that both are symptoms of the same underlying problem.
Comment 11 Holger Voormann CLA 2019-04-01 07:20:53 EDT
(In reply to Thomas Wolf from comment #10)
> 
> [...] But it this the same problem that Holger reported? [...]

Yes, it is the same repo. I asked Harald to add the log.

In EGit 5.3 on Windows 10 this error is reported as "Pipe closed after 0 cycles".
Comment 12 Thomas Wolf CLA 2019-04-01 07:24:42 EDT
(In reply to Holger Voormann from comment #11)
> (In reply to Thomas Wolf from comment #10)
> > 
> > [...] But it this the same problem that Holger reported? [...]
> 
> Yes, it is the same repo. I asked Harald to add the log.
> 
> In EGit 5.3 on Windows 10 this error is reported as "Pipe closed after 0
> cycles".

OK. And it's Advantest. There's an EGit committer at Advantest: Andrey Loskutov. He might be able to debug this directly in the Eclipse debugger! Would be *much* easier than me trying to figure out what's going on by analyzing logs :-) But if you can, post the log before that closing; I'll look at it anyway.
Comment 13 Holger Voormann CLA 2019-04-01 07:46:52 EDT
(In reply to Thomas Wolf from comment #12)
> OK. And it's Advantest. There's an EGit committer at Advantest: Andrey
> Loskutov. He might be able to debug this directly in the Eclipse debugger!
> Would be *much* easier than me trying to figure out what's going on by
> analyzing logs :-) But if you can, post the log before that closing; I'll
> look at it anyway.

CC'ing Andrei.

@Andrei, cloning ssh://socgit.advantest.com:7999/doc/v93000-doc.git with "Apache MINA sshd" fails after some time, but works with "JSch". Could you please take a look at this?
Comment 14 Thomas Wolf CLA 2019-04-02 04:52:44 EDT
I can actually reproduce this now locally. Seems to have something to do with repository size (or the time needed to fetch). I have a huge repo on which I get this. Debugging...
Comment 15 Thomas Wolf CLA 2019-04-02 06:17:12 EDT
Found it. It's a bug in our glue code that makes the connection fail on re-keying. So it's really dependent on repo size.

Fix is a-coming.
Comment 16 Eclipse Genie CLA 2019-04-02 06:41:47 EDT
New Gerrit change created: https://git.eclipse.org/r/139887
Comment 17 Eclipse Genie CLA 2019-04-02 07:30:21 EDT
New Gerrit change created: https://git.eclipse.org/r/139890
Comment 18 Holger Voormann CLA 2019-04-04 04:11:46 EDT
(In reply to Thomas Wolf from comment #15)
> Found it. It's a bug in our glue code that makes the connection fail on
> re-keying. So it's really dependent on repo size.
> 
> Fix is a-coming.

Well done. The Git repository that failed to be cloned can be successfully cloned with JGit/EGit 5.3 with your fix now.

Thanks a lot!
Comment 19 Eclipse Genie CLA 2019-04-21 19:09:24 EDT
Gerrit change https://git.eclipse.org/r/139887 was merged to [stable-5.2].
Commit: http://git.eclipse.org/c/jgit/jgit.git/commit/?id=62675c48de09a30c769bcba06ebf5a312d3b9f8b
Comment 20 torsten piotraschke CLA 2019-05-06 08:51:25 EDT
I'm using Oomph to install Eclipse and to clone a big git repository. I can still see the old e/jgit version 5.3.0 being installed, so I still get the error of the reported issue. I don't find a way to install a newer jgit/egit version into eclipse, since the current p2 repositories only contain the old version.

Is there any way to initiate an update for the update site?
Comment 21 Thomas Wolf CLA 2019-05-06 08:54:13 EDT
Install EGit nightly from https://download.eclipse.org/egit/updates-nightly/ ; it should include this fix.
Comment 22 Matthias Sohn CLA 2019-05-06 08:58:42 EDT
alternatively you can try to install JGit 5.3.1 (we didn't release an egit 5.3.1), its update site is available here:
https://repo.eclipse.org/content/unzip/releases.unzip/org/eclipse/jgit/org.eclipse.jgit.repository/5.3.1.201904271842-r/org.eclipse.jgit.repository-5.3.1.201904271842-r.zip-unzip/
Comment 23 torsten piotraschke CLA 2019-05-06 10:22:37 EDT
Thank you Thomas and Matthias. I went with the nightly update site, which did the trick for me.
Comment 24 Evgenii Pasynkov CLA 2019-05-17 05:51:57 EDT
Hi,

After merging "Apache MINA sshd client: adapt to sshd 2.2.0" into master
(https://git.eclipse.org/c/jgit/jgit.git/commit/?id=86cee68e0d9282ecc6a49792693309e8d5d9d984)
this problem returns back.


Could you please take a look?
Comment 25 Thomas Wolf CLA 2019-05-17 06:22:54 EDT
(In reply to Evgenii Pasynkov from comment #24)
> Hi,
> 
> After merging "Apache MINA sshd client: adapt to sshd 2.2.0" into master
> (https://git.eclipse.org/c/jgit/jgit.git/commit/
> ?id=86cee68e0d9282ecc6a49792693309e8d5d9d984)
> this problem returns back.

Cannot reproduce with JGit master with my huge test repo mentioned in comment 14. Key re-exchange works fine, the repo is cloned successfully.

Make double sure that you use the correct JGit version (5.3.1 or 5.4.0). If so, follow the steps given in comment 5 and post the full log somewhere where I can download it.
Comment 26 Evgenii Pasynkov CLA 2019-05-17 10:40:28 EDT
(In reply to Thomas Wolf from comment #25)

Thank you Thomas.
After deeper investigations, I've narrowed down the problem. For sure, pure PGM-implementation works perfectly. The problem occurs in my code with custom "ProgressMonitor" passed to fetch function, and the severe delays in custom progress monitor implementation - somehow these delays cause timing problems with ssh protocol (I guess).

If you think this problem is worth deeper investigations, then we can go further with logs. Otherwise can leave the issue as "fixed" since workaround is known.

Thank you!