Troubleshooting fork not syncing

Problem

Fork syncing is not happening for a specific repo.

The atlassian-stash.log shows:

2015-06-25 15:25:55,327 ERROR [threadpool:thread-136948]  c.a.s.i.c.StateTransferringExecutor Error while processing asynchronous task
java.lang.NoSuchMethodError: com.atlassian.stash.pull.PullRequestService.findInDirection(Lcom/atlassian/stash/pull/PullRequestDirection;ILjava/lang/String;Lcom/atlassian/stash/pull/PullRequestState;Lcom/atlassian/stash/pull/PullRequestOrder;Lcom/atlassian/stash/util/PageRequest;)Lcom/atlassian/stash/util/Page;
  at com.izymes.workzone.hook.UpdateApprovalHook$1.get(UpdateApprovalHook.java:91) ~[na:na]
  at com.atlassian.stash.util.PagedIterable.iterator(PagedIterable.java:23) ~[stash-util-3.1.5.jar:na]
  at com.izymes.workzone.hook.UpdateApprovalHook.onReceive(UpdateApprovalHook.java:98) ~[na:na]
  at com.atlassian.stash.internal.hook.DefaultBuiltInHookHandlerFactory$2.handle(DefaultBuiltInHookHandlerFactory.java:69) ~[stash-service-impl-3.1.5.jar:na]
  at com.atlassian.stash.internal.hook.DefaultHookService.doHandleRequest(DefaultHookService.java:353) ~[stash-service-impl-3.1.5.jar:na]
  at com.atlassian.stash.internal.hook.DefaultHookService.handleRequest(DefaultHookService.java:339) ~[stash-service-impl-3.1.5.jar:na]
  at com.atlassian.stash.internal.hook.DefaultHookService.handleRawRequest(DefaultHookService.java:250) ~[stash-service-impl-3.1.5.jar:na]
  at com.atlassian.stash.internal.hook.DefaultHookService$2$1.run(DefaultHookService.java:210) ~[stash-service-impl-3.1.5.jar:na]
  at com.atlassian.stash.internal.concurrent.StateTransferringExecutor$StateTransferringRunnable.run(StateTransferringExecutor.java:69) ~[stash-platform-3.1.5.jar:na]
  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0]
  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [na:1.7.0]
  at java.util.concurrent.FutureTask.run(FutureTask.java:166) [na:1.7.0]
  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) [na:1.7.0]
  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) [na:1.7.0]
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0]
  at java.lang.Thread.run(Thread.java:722) [na:1.7.0]
  ... 1 frame trimmed

Diagnosis

In general, these are the guidelines that should be used to analyze fork syncing issues.

• First off, make sure your profiling logging is enabled.
• Generate a  Support Zip (Admin >> Cog Icon >> Atlassian Support Tools >> Support Zip)

• Identify the repo that is problematic. From your application.xml you can, for example, find that the repo CB/ssb is has the ID 391. 

• The important thing now is identifying that the push actually happened. A line similar to that will show up in the profiling logs:

  atlassian-stash-access.log

  2015-06-25 15:25:55,431 | ssh-scm-request-handler | 925x333140x0 | your@email.com | x05ojl
  [0ms] - /usr/local/bin/git receive-pack /software/data/data/repositories/391

• Now you should continue on the profiling logs to see what's happening. As part of processing that push, you should be able to see the pre-receive and post-receive hooks call back into Stash. The output below is for the 391 repo which is failing to fork sync properly:

  ##### Pre-receive hook call #####
  2015-06-25 15:25:55,267 | threadpool:thread-136947 | - | - | -
  [210ms] - DefaultHookService hook callback git-pre-receive for repository 391
    [1ms] - Repository com.atlassian.stash.repository.RepositoryService.getById(int)
      [0ms] - Object com.atlassian.stash.internal.Dao.getById(Object)
    [0ms] - boolean com.atlassian.stash.user.PermissionService.isRepositoryAccessible(Repository)
    [0ms] - ScmHookHandlerFactory com.atlassian.stash.scm.ScmService.getHookHandlerFactory(Repository)
    [204ms] - com.atlassian.stash.internal.hook.DefaultBuiltInHookHandlerFactory$1#preReceive
      [7ms] - com.izymes.workzone.hook.PushToBranchHook#onReceive
        [2ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
      [0ms] - com.atlassian.stash.internal.scm.git.pull.PullRequestRefGuardHook#onReceive
      [189ms] - com.atlassian.stash.internal.hook.repository.PreReceiveRepositoryHookAdapter#onReceive
        [185ms] - boolean com.atlassian.stash.internal.hook.repository.InternalRepositoryHookService.visitEnabledHooks(Repository,Class,RepositoryHookSettingsCallback)
          [2ms] - List com.atlassian.stash.internal.hook.repository.RepositoryHookStatusDao.findEnabledHooks(InternalRepository,Collection)
          [4ms] - Map com.atlassian.stash.internal.repository.InternalRepositorySettingsService.findByRepository(Repository,Collection)
            [3ms] - Iterable com.atlassian.stash.internal.repository.RepositorySettingsDao.findByRepository(InternalRepository,Collection)
          [0ms] - com.atlassian.stash.plugin.hooks.protectbranch.ProtectUnmergedBranchHook#onReceive
          [117ms] - com.atlassian.stash.plugin.hooks.forcepush.ForcePushHook#onReceive
            [0ms] - boolean com.atlassian.stash.user.PermissionService.isRepositoryAccessible(Repository)
            [0ms] - Ticket com.atlassian.stash.throttle.ThrottleService.acquireTicket(String)
            [112ms] - Page com.atlassian.stash.commit.CommitService.getChangesetsBetween(ChangesetsBetweenRequest,PageRequest)
              [0ms] - ScmCommandFactory com.atlassian.stash.scm.ScmService.getCommandFactory(Repository)
              [105ms] - /usr/local/bin/git rev-list --format=%H%x02%h%x02%P%x02%p%x02%aN%x02%aE%x02%at%n%B%n%x03 --ignore-missing --stdin --
              [0ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
              [0ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
              [0ms] - Map com.atlassian.stash.internal.content.IndexedChangesetDao.getAttributesForChangesets(Collection,Collection)
              [0ms] - Map com.atlassian.stash.internal.repository.RepositoryActivityDao.countCommentsByCommit(int,Set)
              [0ms] - Map com.atlassian.stash.internal.user.InternalUserService.mapUsersByEmail(Set)
          [62ms] - com.teslamotors.stash.logchecker.CommitLogMessagePreReceiveHook#onReceive
      [8ms] - com.atlassian.stash.hooks.permissions.internal.BranchPermissionHook#onReceive
  
   
  ##### Post-receive hook call #####
  2015-06-25 15:25:55,324 | threadpool:thread-136948 | - | - | -
  [10ms] - DefaultHookService hook callback git-post-receive for repository 391
    [0ms] - Repository com.atlassian.stash.repository.RepositoryService.getById(int)
      [0ms] - Object com.atlassian.stash.internal.Dao.getById(Object)
    [0ms] - boolean com.atlassian.stash.user.PermissionService.isRepositoryAccessible(Repository)
    [0ms] - ScmHookHandlerFactory com.atlassian.stash.scm.ScmService.getHookHandlerFactory(Repository)
    [5ms] - com.atlassian.stash.internal.hook.DefaultBuiltInHookHandlerFactory$2#postReceive
      [5ms] - com.izymes.workzone.hook.UpdateApprovalHook#onReceive
        [0ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)

•  The DefaultHookService hook callback git-post-receive for repository 391 trace shows the problem. It hits the Workzone for Stash plugin and that's the last thing shown on com.izymes.workzone.hook.UpdateApprovalHook#onReceive. 
  
  

• This is how the post-receive output for a repository where fork syncing is working should look:

  2015-06-25 15:18:31,191 | threadpool:thread-136704 | - | - | -
  [30ms] - DefaultHookService hook callback git-post-receive for repository 427
    [0ms] - Repository com.atlassian.stash.repository.RepositoryService.getById(int)
      [0ms] - Object com.atlassian.stash.internal.Dao.getById(Object)
    [0ms] - boolean com.atlassian.stash.user.PermissionService.isRepositoryAccessible(Repository)
    [1ms] - ScmHookHandlerFactory com.atlassian.stash.scm.ScmService.getHookHandlerFactory(Repository)
    [24ms] - com.atlassian.stash.internal.hook.DefaultBuiltInHookHandlerFactory$2#postReceive
      [5ms] - com.izymes.workzone.hook.UpdateApprovalHook#onReceive
        [2ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
      [19ms] - com.atlassian.stash.internal.hook.PushPostReceiveHook#onReceive

• • Notice that, after the Workzone hook, repository 427's callback hits the PushPostReceiveHook. That hook raises RepositoryPushEvent, which in turn triggers fork syncing. Since that's not called for CB/ssb, fork syncing doesn't run.
  • Notice that the thread ID, threadpool:thread-136948, is the same between the Workzone stack trace and the post-receive callback entry in the profiling logs. As you can see, the outdated version of the Workzone plugin is calling a method that was removed in Stash 3.0.

Cause

The PushPostReceiveHook was not called on the example above because the Workzone plugin was outdated. The instance (Stash 3.1.5.) was running Workzone 1.3.1. According to its version history, 1.3.1 is compatible with Stash 2.5.0-2.12.6. When the instance was upgraded that plugin was broken causing the logs reported on the problem description.

Workaround

Disable the Workzone Plugin.

Resolution

Look at the plugin version history and upgrade it to a version that is compatible with your Stash instance.