nav[aria-label="Primary Navigation"] { padding: 0; & ul { list-style: none; width: 100%; display: flex; flex-direction: row; justify-content: start; align-items: start; gap: 30px; padding: 0; & li { margin: 0; } & ul li { list-style: none; } } }

Unexpected exceptions while cloning

GeorgG

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 &gt; git rev-parse --is-inside-work-tree # timeout=10
14:58:35 Fetching changes from the remote Git repository
14:58:35 &gt; 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 &gt; git --version # timeout=10
14:58:35 using GIT_SSH to set credentials 
14:58:35 &gt; 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

Accepted answers

All comments

Balázs Szakmáry

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 Kulla1

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

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

I have to agree with Christoph here.

GeorgG

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

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

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.

Kjetil Nygård

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...

Balázs Szakmáry

Have you tried the same thing with Awesome Graphs disabled?

Welcome!

It looks like you're new here. Sign in or register to get started.

Quick Links

Find more posts tagged with

bitbucket-server

bitbucket-administration