STASH - com.atlassian.stash.exception.ServerException: An error occurred while executing an external process: process timed out

[Mark Bockstael]

Hi,

a few weeks ago we started encountering time-out errors when running a REST call to create change-logs on our repo.
In the logging we find this :

2015-02-10 17:03:00,988 ERROR [http-nio-6088-exec-142] jd22743 @1PL5RB0x1023x488880x2 cjzc56 10.46.24.184 "GET /scm/<project>/<repo>.git/info/refs HTTP/1.1" c.a.s.i.s.g.p.h.GitSmartExitHandler Request for repo 'repo' of project 'project' from '10.46.24.184' failed: read process '/opt/git/bin/git http-backend' caused an exception
2015-02-10 17:03:23,125 ERROR [http-nio-6088-exec-71] @1PL5RB0x1023x489034x1 1al4sv0 10.46.33.72 "GET /mvc/error500 HTTP/1.1" c.a.s.i.web.ErrorPageController There was an unhandled exception loading [/rest/api/1.0/projects/<project>/repos/<repo>/commits]
com.atlassian.stash.exception.ServerException: An error occurred while executing an external process: process timed out
 at com.atlassian.stash.scm.git.common.command.GitCommandExitHandler.evaluateThrowable(GitCommandExitHandler.java:104) ~[na:na]
 at com.atlassian.stash.scm.git.common.command.GitCommandExitHandler.onError(GitCommandExitHandler.java:148) ~[na:na]
 at com.atlassian.stash.scm.DefaultCommandExitHandler.onExit(DefaultCommandExitHandler.java:33) ~[DefaultCommandExitHandler.class:na]
 at com.atlassian.stash.scm.BaseCommand.callExitHandler(BaseCommand.java:138) ~[BaseCommand.class:na]
 at com.atlassian.stash.scm.BaseCommand$CommandFuture.internalGet(BaseCommand.java:251) ~[BaseCommand$CommandFuture.class:na]
 at com.atlassian.stash.scm.BaseCommand$CommandFuture.get(BaseCommand.java:220) ~[BaseCommand$CommandFuture.class:na]
 at com.atlassian.stash.scm.BaseCommand.call(BaseCommand.java:75) ~[BaseCommand.class:na]
 at com.atlassian.stash.internal.commit.DefaultCommitService.streamChangesetsBetween(DefaultCommitService.java:313) ~[DefaultCommitService.class:na]
 at com.atlassian.stash.internal.rest.commit.CommitResource$2.write(CommitResource.java:121) ~[na:na]
 at com.atlassian.stash.rest.util.JsonStreamingOutput.write(JsonStreamingOutput.java:22) ~[na:na]
 at com.atlassian.stash.internal.rest.filter.StreamingOutputResponseFilter$ExceptionMappingStreamingOutput.write(StreamingOutputResponseFilter.java:46) ~[na:na]
 at com.atlassian.applinks.core.rest.context.ContextFilter.doFilter(ContextFilter.java:25) ~[na:na]
 at com.atlassian.stash.internal.spring.security.StashAuthenticationFilter.onSuccess(StashAuthenticationFilter.java:224) ~[StashAuthenticationFilter.class:na]
 at com.atlassian.stash.internal.spring.security.StashAuthenticationFilter.doFilter(StashAuthenticationFilter.java:101) ~[StashAuthenticationFilter.class:na]
 at com.atlassian.stash.internal.web.auth.BeforeLoginPluginAuthenticationFilter.doInsideSpringSecurityChain(BeforeLoginPluginAuthenticationFilter.java:111) ~[BeforeLoginPluginAuthenticationFilter.class:na]
 at com.atlassian.stash.internal.web.auth.BeforeLoginPluginAuthenticationFilter.doFilter(BeforeLoginPluginAuthenticationFilter.java:77) ~[BeforeLoginPluginAuthenticationFilter.class:na]
 at com.atlassian.security.auth.trustedapps.filter.TrustedApplicationsFilter.doFilter(TrustedApplicationsFilter.java:100) ~[TrustedApplicationsFilter.class:na]
 at com.atlassian.oauth.serviceprovider.internal.servlet.OAuthFilter.doFilter(OAuthFilter.java:69) ~[na:na]
 at com.atlassian.analytics.client.filter.DefaultAnalyticsFilter.doFilter(DefaultAnalyticsFilter.java:33) ~[na:na]
 at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31) ~[AbstractHttpFilter.class:na]
 at com.atlassian.stash.internal.web.auth.BeforeLoginPluginAuthenticationFilter.doBeforeBeforeLoginFilters(BeforeLoginPluginAuthenticationFilter.java:89) ~[BeforeLoginPluginAuthenticationFilter.class:na]
 at com.atlassian.stash.internal.web.auth.BeforeLoginPluginAuthenticationFilter.doFilter(BeforeLoginPluginAuthenticationFilter.java:75) ~[BeforeLoginPluginAuthenticationFilter.class:na]
 at com.atlassian.stash.internal.request.DefaultRequestManager.doAsRequest(DefaultRequestManager.java:84) ~[DefaultRequestManager.class:na]
 at com.hazelcast.web.WebFilter.doFilter(WebFilter.java:450) ~[WebFilter.class:3.3-RC3]
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]
 at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
 ... 246 frames trimmed
Caused by: com.atlassian.utils.process.ProcessTimeoutException: process timed out
 at com.atlassian.utils.process.ExternalProcessImpl.wrapUpProcess(ExternalProcessImpl.java:656) ~[ExternalProcessImpl.class:na]
 at com.atlassian.utils.process.ExternalProcessImpl.finish(ExternalProcessImpl.java:161) ~[ExternalProcessImpl.class:na]
 at com.atlassian.stash.scm.BaseCommand$CommandFuture.get(BaseCommand.java:218) ~[BaseCommand$CommandFuture.class:na]
 ... 21 common frames omitted

I found a reference to a time-out setting (https://jira.atlassian.com/browse/STASH-4129), but i was unable to find anything related to this in the documentation (https://confluence.atlassian.com/display/STASH033/Stash+config+properties)

We're running STASH v3.3.1.

Any clues as to why this might be happening?

[Michael Heemskerk · Accepted solution]

First of all, The timeout configuration setting that's described in STASH-4129 does not apply to /rest/api/latests/projects/<project>/repos/<repo>/commits endpoint. If you want to tune the process timeout setting, you should tune either process.execution.timeout or process.idle.timeout as described in the Process Execution section.

As to why the operation times out, it's hard to say just from the stack trace. There could be a number of reasons:

• your script(?) that does the REST call does not consume any of the output and the git process times out because its output hasn't been read for more than 60s, or the script does read some, but not all of the data and does not close the HTTP connection?
• for some reason the git rev-list command that is started takes more than 120s to complete.
• for some reason the git rev-list command takes more than 60s before the first output appears. 

Does this happen to all repositories or is it just a single repository? Try to do the same REST call using curl from the command line and time how long it takes and whether you get any output.

If the git command really is slow, there might still be a host of reasons. The disk could be slow, or if you're using a network filesystem such as NFS, the latency could be high resulting in slow disk I/O. Or the repository could have a large number of loose objects or lots of small pack files, which can also slow down git operations. 

If the problem persists, I'd suggest:

• Enable profiling (Administration > Logging and Profiling)
• Reproduce the problem a few times
• Leave on profiling for some time to also collect performance information for other operations
• Create a support zip (Administration > Atlassian Support Tools > Support Zip)
• Open a support ticket on https://support.atlassian.com and upload the support zip.

[Mark Bockstael]

Hi Michael,

thanks for replying!

in the mean time, our devs have altered their script (indeed, it was a script) to compile the changelogs for sets of 10 issues at a time. This effectively lets the processes end within the default allotted time.

I'll keep in mind your suggestion to maybe tune the process.xxx.timeouts, if the need occurs

kind regards

Mark

[Michael Heemskerk]

If you're trying to retrieve the list of commits for a set of JIRA issues, there's a more efficient way. You can retrieve all commits for a particular JIRA issue using https://developer.atlassian.com/static/rest/stash/3.7.2/stash-jira-integration-rest.html#idp452416

[Mark Bockstael]

i believe this is what they are using in the script. but I'll fwd the link to them just in case :-)