Unexpected exceptions while cloning

GeorgG January 19, 2015

Hi all,

one of our users reported problems during a stress test involving cloning repositories from our Stash instance. The problem occurred repeatedly on executing the stress test. Here's the users error message:

14:58:35 Started by upstream project "*****" build number 161
14:58:35 originally caused by:
14:58:35 Started by upstream project "***" build number 229
14:58:35 originally caused by:
14:58:35   Started by timer
14:58:35 Building remotely on ******* (docker swarm linux) in workspace /home/***/system/3
14:58:35 > git rev-parse --is-inside-work-tree # timeout=10
14:58:35 Fetching changes from the remote Git repository
14:58:35 > git config remote.origin.url ssh://git@***:7999/***/***.git # timeout=10
14:58:35 Fetching upstream changes from ssh://git@***:7999/***/***.git
14:58:35 > git --version # timeout=10
14:58:35 using GIT_SSH to set credentials 
14:58:35 > git fetch --tags --progress ssh://git@***:7999/***/***.git +refs/heads/*:refs/remotes/origin/*
14:58:36 ERROR: Error fetching remote repo 'origin'
14:58:36 ERROR: Error fetching remote repo 'origin'
14:58:36 Skipping publisher since build result is FAILURE
14:58:36 Recording test results
14:58:36 ERROR: Publisher hudson.tasks.junit.JUnitResultArchiver aborted due to exception
14:58:36 hudson.AbortException: Test reports were found but none of them are new. Did tests run? 
14:58:36 For example, /home/***/fsroot/workspace/***/label/docker/system/3/products/linux-gcc-32-ninja-debug/profiling/***/src/FrancaProfilingService_fidl_test.xml is 16 min old

And here's the corresponding excerpt from the server log:

354217 2015-01-15 14:58:36,300 DEBUG [threadpool:thread-2633054] ASF1HI @Y3BODBx898x4426466x6 10r1j0h 10.34.106.188 SSH - git-upload-pack '/asf/asf.git' c.a.s.i.s.g.p.ssh.GitSshExitHandler Exception from process was:
354218 com.atlassian.utils.process.ProcessException: java.lang.RuntimeException: Failed to copy stream from git process to ssh client
354219     at com.atlassian.utils.process.ExternalProcessImpl.handleHandlerError(ExternalProcessImpl.java:476) ~[ExternalProcessImpl.class:na]
354220     at com.atlassian.utils.process.ExternalProcessImpl.access$100(ExternalProcessImpl.java:18) ~[ExternalProcessImpl.class:na]
354221     at com.atlassian.utils.process.ExternalProcessImpl$AbstractHandlerRunnable.onError(ExternalProcessImpl.java:684) ~[ExternalProcessImpl$AbstractHandlerRunnable.class:na]
354222     at com.atlassian.utils.process.ExternalProcessImpl$AbstractHandlerRunnable.doTask(ExternalProcessImpl.java:679) ~[ExternalProcessImpl$AbstractHandlerRunnable.class:na]
354223     at com.atlassian.utils.process.LatchedRunnable.run(LatchedRunnable.java:158) ~[LatchedRunnable.class:na]
354224     at com.atlassian.utils.process.ExternalProcessImpl$AsynchronousOutputHandlerRunnable.run(ExternalProcessImpl.java:698) ~[ExternalProcessImpl$AsynchronousOutputHandlerRunnable.class:na]
354225     at com.atlassian.stash.internal.concurrent.StateTransferringExecutor$StateTransferringRunnable.run(StateTransferringExecutor.java:69) ~[StateTransferringExecutor$StateTransferringRunnable.class:na]
354226     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_72]
354227     at java.lang.Thread.run(Thread.java:745) ~[na:1.7.0_72]
354228     ... 1 frame trimmed
354229 Caused by: java.lang.RuntimeException: Failed to copy stream from git process to ssh client
354230     at com.atlassian.stash.internal.scm.git.protocol.ssh.GitSshOutputHandler.process(GitSshOutputHandler.java:42) ~[na:na]
354231     at com.atlassian.stash.scm.SummarizingProcessHandler$DelegatingInputStreamHandler.process(SummarizingProcessHandler.java:184) ~[SummarizingProcessHandler$DelegatingInputStreamHandler.class:na]
354232     at com.atlassian.stash.scm.SummarizingProcessHandler$DelegatingInputStreamHandler.process(SummarizingProcessHandler.java:166) ~[SummarizingProcessHandler$DelegatingInputStreamHandler.class:na]
354233     at com.atlassian.stash.scm.SummarizingProcessHandler.processOutput(SummarizingProcessHandler.java:92) ~[SummarizingProcessHandler.class:na]
354234     at com.atlassian.utils.process.ExternalProcessImpl$OutputHandlerRunnable.process(ExternalProcessImpl.java:764) ~[ExternalProcessImpl$OutputHandlerRunnable.class:na]
354235     at com.atlassian.utils.process.ExternalProcessImpl$AbstractHandlerRunnable.doTask(ExternalProcessImpl.java:677) ~[ExternalProcessImpl$AbstractHandlerRunnable.class:na]
354236     ... 6 common frames omitted
354237 Caused by: java.io.InterruptedIOException: null
354238     at java.io.PipedInputStream.awaitSpace(PipedInputStream.java:276) ~[na:1.7.0_72]
354239     at java.io.PipedInputStream.receive(PipedInputStream.java:232) ~[na:1.7.0_72]
354240     at java.io.PipedOutputStream.write(PipedOutputStream.java:149) ~[na:1.7.0_72]
354241     at com.atlassian.stash.internal.scm.git.protocol.ssh.GitSshOutputHandler.process(GitSshOutputHandler.java:34) ~[na:na]
354242     ... 11 common frames omitted
354243 2015-01-15 14:58:36,306 DEBUG [NioProcessor-2]  c.a.s.s.c.s.CachingSshUploadPackRequest ASF/asf Canceling SSH git-upload-pack
354244 2015-01-15 14:58:36,306 DEBUG [NioProcessor-4]  c.a.s.s.c.s.CachingSshUploadPackRequest ASF/asf Canceling SSH git-upload-pack
354245 2015-01-15 14:58:36,321 DEBUG [ssh-scm-request-handler] ASF1HI @Y3BODBx898x4426466x6 10r1j0h 10.34.106.188 SSH - git-upload-pack '/asf/asf.git' c.a.s.s.c.s.CachingSshUploadPackRequest [ASF/asf[509]] Exception encountered while processing a git-upload-pack request
354246 java.io.IOException: Premature EOF detected. Expected 93 bytes, but only 15 were available
354247     at com.atlassian.stash.scm.cache.git.GitUtils.checkBytesRead(GitUtils.java:146) ~[na:na]
354248     at com.atlassian.stash.scm.cache.git.GitUtils.readPacket(GitUtils.java:139) ~[na:na]
354249     at com.atlassian.stash.scm.cache.ssh.UploadPackProxy.copyUntilFlush(UploadPackProxy.java:271) ~[na:na]
354250     at com.atlassian.stash.scm.cache.ssh.UploadPackProxy.streamRefs(UploadPackProxy.java:233) ~[na:na]
354251     at com.atlassian.stash.scm.cache.ssh.CachingSshUploadPackRequest.handleRequest(CachingSshUploadPackRequest.java:151) ~[na:na]
354252     at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable$1.withRequest(SshScmRequestCommandAdapter.java:289) [stash-ssh-3.3.2_1412807880000.jar:na]
354253     at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable$1.withRequest(SshScmRequestCommandAdapter.java:277) [stash-ssh-3.3.2_1412807880000.jar:na]
354254     at com.atlassian.stash.internal.request.DefaultRequestManager.doAsRequest(DefaultRequestManager.java:84) [DefaultRequestManager.class:na]
354255     at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable.run(SshScmRequestCommandAdapter.java:277) [stash-ssh-3.3.2_1412807880000.jar:na]
354256     at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) [stash-ssh-3.3.2_1412807880000.jar:na]
354257     at com.atlassian.stash.internal.concurrent.StateTransferringExecutor$StateTransferringRunnable.run(StateTransferringExecutor.java:69) [StateTransferringExecutor$StateTransferringRunnable.class:na]
354258     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_72]
354259     at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_72]

 

Can you advise when the root cause of the problem might be and how we can fix the issue?

 

Here are the details on our installation:

  • OS: RHEL6
  • Stash: 3.3.2
  • git: 1.7.11.3

Please let me know if you need further information.

Thanks in advance for your help and cheers,

Georg

4 answers

0 votes
Balázs Szakmáry
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
March 8, 2015

Have you tried the same thing with Awesome Graphs disabled?

0 votes
Kjetil Nygård March 8, 2015

We are also experiencing this problem, when running from the commandline in parallel (100x):

git fetch --all
git fetch --tags

 

Then we get the exception in the **/var/atlassian/application-data/stash/log/atlassian-stash.log**

2015-03-09 07:37:51,314 WARN  [ssh-scm-request-handler]  c.a.s.i.s.s.SshScmRequestCommandAdapter Exception encountered handling SSH command 'git-upload-pack '/our/repository.git''
java.io.IOException: Premature EOF detected. Expected 69 bytes, but only -1 were available
        at com.atlassian.stash.scm.cache.git.GitUtils.checkBytesRead(GitUtils.java:146) ~[na:na]
        at com.atlassian.stash.scm.cache.git.GitUtils.readPacket(GitUtils.java:139) ~[na:na]
        at com.atlassian.stash.scm.cache.ssh.UploadPackProxy.copyUntilFlush(UploadPackProxy.java:271) ~[na:na]
        at com.atlassian.stash.scm.cache.ssh.UploadPackProxy.streamRefs(UploadPackProxy.java:233) ~[na:na]
        at com.atlassian.stash.scm.cache.ssh.CachingSshUploadPackRequest.handleRequest(CachingSshUploadPackRequest.java:151) ~[na:na]
        at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable$1.withRequest(SshScmRequestCommandAdapter.java:281) ~[stash-ssh-3.7.0.jar:na]
        at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable$1.withRequest(SshScmRequestCommandAdapter.java:268) ~[stash-ssh-3.7.0.jar:na]
        at com.atlassian.stash.internal.request.DefaultRequestManager.doAsRequest(DefaultRequestManager.java:85) ~[stash-service-impl-3.7.0.jar:na]
        at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable.perform(SshScmRequestCommandAdapter.java:268) [stash-ssh-3.7.0.jar:na]
        at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable.perform(SshScmRequestCommandAdapter.java:238) [stash-ssh-3.7.0.jar:na]
        at com.atlassian.stash.internal.user.DefaultEscalatedSecurityContext.call(DefaultEscalatedSecurityContext.java:60) [stash-service-impl-3.7.0.jar:na]
        at com.atlassian.stash.internal.ssh.server.SshScmRequestCommandAdapter$ScmRequestRunnable.run(SshScmRequestCommandAdapter.java:312) [stash-ssh-3.7.0.jar:na]
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) [stash-ssh-3.7.0.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_76]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_76]
        ... 26 frames trimmed

 

 

 When running monitoring on the JVM, we see that we have allocated 2gb memory, but stash only uses about 300mb when this happens. The CPU usage is also low.

 

PS: We do have the "Awesome Graphs for Stash" plugin enabled...

 

0 votes
GeorgG January 20, 2015

Hey Balazs. Our Stash server currently does not have profiling activated. But I found this in the log:

    2015-01-15 14:58:14,928 INFO [hz.hazelcast.HealthMonitor] com.hazelcast.util.HealthMonitor [10.3.133.199]:5701 [bamboo-agent] [3.3-RC3] memory.used=532.8M, memory.free=145.7M, memory.total=678.5M, memory.max=683.0M, memory.used /total=78.52%, memory.used/max=78.00%, load.process=3.00%, load.system=4.00%, load.systemAverage=9.00%, thread.count=229, thread.peakCount=335, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.query.s ize=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operation.size=0, executor.q.priorityOperation.size=0, executor.q.response.size=0, operations.remote.size=1, operations.running.size=0 , proxy.count=1260, clientEndpoint.count=0, connection.active.count=0, connection.count=0

Is this what you're looking for and if yes, do you see a load problem?

GeorgG January 20, 2015

I have also activated profiling now. Christoph and I will collaborate to get a picture of the load situation at the time of a crash.

Balázs Szakmáry
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 20, 2015

I don't work for Atlassian :) If you cannot spot the problem in the logs yourself, I think you should open a support request and they will help you.

0 votes
Balázs Szakmáry
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 19, 2015

Looks like one of your plugins (something to do with Hudson/Jenkins and/or JUnit) is malfunctioning. You need to either disable it or fix it.

Christoph Kulla January 20, 2015

I find your answer misleading. Please take a look at the jenkins log at the beginning:

14:58:36 ERROR: Error fetching remote repo 'origin'
14:58:36 ERROR: Error fetching remote repo 'origin'

Here it says it can't fetch from the repo. Aftewards jenkins fails to parse junit reports because the project was not build due to the above error.

We see this error every now and then during our stress test. It seems like Stash is not always serving request well under load.

Balázs Szakmáry
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 20, 2015

Sorry about that, you wrote "Here's the users error message", there was nothing about all this happening in Jenkins. To the point: check the resource usage of Stash while you are running this test. Also, this: https://confluence.atlassian.com/display/STASH/Scaling+Stash might be useful.

GeorgG January 20, 2015

I have to agree with Christoph here.

Suggest an answer

Log in or Sign up to answer
TAGS
AUG Leaders

Atlassian Community Events