[8.0.1] Cannot fork repository

Same problem over there. I was using Gitlab 7.14.3 and I'm having the fork problem after upgrading to Gitlab 8.0.1

Same here. After upgrade to 8.0.1 I cannot fork existing repo.

The funny thing is, that this refers only to "Project" tab. Every other tab works just fine. I can even clone new repo.

Could you try to run git gc on that specific repository in /var/opt/gitlab/git-data/repository ? Make sure you are using the correct user account don't use root.

Can you also look in /var/log/gitlab/sidekiq/current and see if there are any errors there running the fork worker?

@ayufan The API errors here looks like a runner trying to run a build. Any ideas why this error is shown here?

@stanhu This looks like a misconfigured nginx, or misconfigured gitlab-runner URL not having the /ci.

@torzech Can you post your nginx config?

@jnijhof No change.

@ayufan Here they are:

nginx.conf gitlab-http.conf

@torzech Can you post the Sidekiq log as described above? I'm not sure the API CI errors are necessarily related.

@stanhu I've forked another repository and that's the result in sidekiq log:

2015-09-24_17:20:36.89340 2015-09-24T17:20:36.893Z 1533 TID-bzpng RepositoryForkWorker JID-215e51fbb3c5bf1b9cec4afa INFO: start
2015-09-24_17:20:37.26154 2015-09-24T17:20:37.261Z 1533 TID-bvdw8 ProjectCacheWorker JID-d989324e7bf0d08c5316e2f0 INFO: start
2015-09-24_17:20:37.29720 2015-09-24T17:20:37.296Z 1533 TID-bzpng RepositoryForkWorker JID-215e51fbb3c5bf1b9cec4afa INFO: done: 0.404 sec
2015-09-24_17:20:37.33756 2015-09-24T17:20:37.337Z 1533 TID-bvdw8 ProjectCacheWorker JID-d989324e7bf0d08c5316e2f0 INFO: done: 0.076 sec

That seems to suggest the fork was successful. Can go into the Files tab and browse fine?

Yes. All tabs except "Project" work fine. I can clone new repository. I can even make and accept merge requests with the source repository.

I had the same result. The first fork stayed endless in "Forking in progress"...but I deleted the project and I created a new fork, and it succeed

Ok, it does sound like the API error may be the root cause here. @ayufan, it looks like the POST request is coming from within the server host (127.0.0.1), not an external CI runner. Is the main project page trying to hit the CI API request?

@ares86 No luck for me.

But wait... You've deleted the main project or just the forked one?

@torzech Do you use CI? What is your configuration?

@stanhu This looks like "default nginx host" case. We had problem in Omnibus (should be patched in 8.0.2) when the use of ci_external_url would not create nginx config. I think that in that case the nginx config for previous CI is not created, runners still try to talk to address specified in ci_external_url, but there's no nginx config to handle that address. So, the request are handled by default and only nginx host, the GitLab.

@torzech One thing I don't quite understand is why the project page is getting hung up on the message. Can you open your browser's "Inspect Element" and see if there are any JavaScript errors in the console?

@stanhu I don't see any errors, but I do have XHR requests (every 5s) to http://DOMAINS/NAMESPACE/REPO_NAME/import. The requests return html page (the same as I'm currently at).

Ok, so it sounds like for some reason import_status in the DB may not be set to the right value for some reason. Do you have access to the DB? For omnibus installations, you can do something like this:

$ sudo -u gitlab-psql psql -h /var/opt/gitlab/postgresql -d gitlabhq_production
gitlabhq_production=# SELECT import_status from projects where path = '<YOUR REPO_NAME>';
 import_status 
---------------
 finished
(1 row)

Here's the response.

 import_status 
---------------
 none
 started
(2 rows)

The first one is the original repository, second one - fork.

Wow, that's strange. The second one should read finished after the Sidekiq task completes in RepositoryForkWorker. I'm not sure why the DB didn't update in your case. I tried forking large repos on GitLab.com, and things worked fine there.

@DouweM, have you seen any cases where the state machine didn't save to the DB?

You could manually update the DB to "finished" as a workaround for now.

@torzech One possibility is that the DB ran into some validation error for that project record when it attempted to save. Perhaps you could show the output of SELECT * from projects where path = '<YOUR REPO_NAME>'?

It may be helpful to use expanded display in Postgres via \x.

gitlabhq_production=# SELECT * from projects where path = '<REPO_NAME>';
-[ RECORD 1 ]----------+---------------------------
id                     | 12
name                   | <REPO_NAME>
path                   | <REPO_NAME>
description            | <REPO_DESCRIPTION>
created_at             | 2015-09-16 12:09:57.016126
updated_at             | 2015-09-17 06:58:53.590819
creator_id             | 1
issues_enabled         | t
wall_enabled           | f
merge_requests_enabled | t
wiki_enabled           | t
namespace_id           | 3
issues_tracker         | gitlab
issues_tracker_id      | 
snippets_enabled       | f
last_activity_at       | 2015-09-16 17:02:45.218972
import_url             | 
visibility_level       | 10
archived               | f
avatar                 | 
import_status          | none
repository_size        | 0.32
star_count             | 0
import_type            | 
import_source          | 
commit_count           | 28
-[ RECORD 2 ]----------+---------------------------
id                     | 78
name                   | <REPO_NAME>
path                   | <REPO_NAME>
description            | <REPO_DESCRIPTION>
created_at             | 2015-09-24 18:10:13.554025
updated_at             | 2015-09-24 18:10:15.811182
creator_id             | 1
issues_enabled         | t
wall_enabled           | f
merge_requests_enabled | t
wiki_enabled           | t
namespace_id           | 1
issues_tracker         | gitlab
issues_tracker_id      | 
snippets_enabled       | f
last_activity_at       | 2015-09-24 18:10:13.554025
import_url             | 
visibility_level       | 10
archived               | f
avatar                 | 
import_status          | started
repository_size        | 0.32
star_count             | 0
import_type            | 
import_source          | 
commit_count           | 16

I'm baffled by this one. Looks like the records are good, unless there is something in the description/name/path that I'm not seeing.

Does this happen consistently, no matter what you try? The only thing I can suggest is hack /opt/gitlab/embedded/service/gitlab-rails/app/workers/repository_fork_worker.rb and see if we can figure out where it's going wrong:

   if project.valid_repo?
      ProjectCacheWorker.perform_async(project.id)
      logger.info("Import status before: #{project.import_status}") # Added
      project.import_finish
      logger.info("Import status after: #{project.import_status}") # Added
    else
      project.import_fail
      logger.error("Project #{id} had an invalid repository after fork")
    end

    logger.info("Import status before save: #{project.import_status}, changed? #{project.changed?}") # Added
    project.save
    logger.info("Import status after save: #{project.import_status}, changed? #{project.changed?}") # Added

  end

Be sure to run gitlab-ctl restart sidekiq if you do try this. The log messages should appear in the Sidekiq log.

For clarity, I've removed the timestamps.

INFO: Booting Sidekiq 3.3.0 with redis options {:url=>"unix:/var/opt/gitlab/redis/redis.socket", :namespace=>"resque:gitlab"}
INFO: Running in ruby 2.1.6p336 (2015-04-13 revision 50298) [x86_64-linux]
INFO: See LICENSE and the LGPL-3.0 for licensing details.
INFO: Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org/pro
INFO: Starting processing, hit Ctrl-C to stop
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: start
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: Import status before: started
ProjectCacheWorker JID-6ef2b9b88d108e80433c02b1 INFO: start
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: Import status after: finished
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: Import status before save: finished, changed? false
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: Import status after save: finished, changed? false
RepositoryForkWorker JID-a0a4e8f17a470a5b755ec15f INFO: done: 0.498 sec
ProjectCacheWorker JID-6ef2b9b88d108e80433c02b1 INFO: done: 0.15 sec

And... this time it worked!

I've removed Your changes and everything looks OK.

I wonder what was wrong...

Thanks for trying. It sounds like there is some race condition. Maybe since RepositoryForkWorker and ProjectCacheWorker are both trying to update the same entry in the database that something goes wrong. It may have helped by adding these print statements that the timing changed. I wonder if calling import_finished before we launch the task helps:

  if project.valid_repo?
      project.import_finish
      ProjectCacheWorker.perform_async(project.id)
    else
      project.import_fail
    end

  project.save

@stanhu I've already edited my previous answer. Everything works right now.

I wrote it too soon. 2 forks were OK, but another one "crashed".

I've changed order as You suggested, but no luck. Forking doesn't work again.

@stanhu You may be right about that "race". When I add "sleep 1" between those lines in "if project.valid_repo?", everything works just fine. ;)

    if project.valid_repo?
      project.import_finish
      sleep 1
      ProjectCacheWorker.perform_async(project.id)
    else
      project.import_fail
      logger.error("Project #{id} had an invalid repository after fork")
    end

@torzech Yeah, I think it's an issue with the transaction not being committed at the right time, although I haven't been able to reproduce the same issue despite forking many times.

Can you try one more thing? This might help:

    if project.valid_repo?
      Project.transaction do
        project.import_finish
      end

      ProjectCacheWorker.perform_async(project.id)

I've found that I can get one and only one fork per boot of the server. After the server boots up, I can fork a project and it succeeds very quickly. After that, every fork I try is stuck in the "forking in progress" state. Deleting the forks, and recreating them doesn't work until I reboot the server and then I can fork just one project again.

@ngarner_testout Can you check the Sidekiq log and the database as described in the above notes? I just want to confirm that you're seeing the same issue. Can you click around the Files section after you see the "Forking in progress" message?

Yes, I can click on browse through the files of the fork on the GitLab server site, and the bad fork does show up in the list of projects and has the correct amount of disk space showing up for it in the admin area.

Here are all the entries from the sidekiq log that appeared when I tried the most recent fork and had it stall...

2015-09-25_04:21:27.80347 2015-09-25T04:21:27.803Z 1063 TID-dspt0 RepositoryForkWorker JID-ffbd4f2b38ed1f7aaa488b30 INFO: start
2015-09-25_04:21:28.40757 2015-09-25T04:21:28.407Z 1063 TID-duzpw ProjectCacheWorker JID-235977d140e1e1634986f4e8 INFO: start
2015-09-25_04:21:28.54055 2015-09-25T04:21:28.540Z 1063 TID-duzpw ProjectCacheWorker JID-235977d140e1e1634986f4e8 INFO: done: 0.133 sec
2015-09-25_04:21:28.54155 2015-09-25T04:21:28.541Z 1063 TID-dspt0 RepositoryForkWorker JID-ffbd4f2b38ed1f7aaa488b30 INFO: done: 0.738 sec
2015-09-25_04:21:47.00484 2015-09-25T04:21:47.004Z 1063 TID-dspt0 GitlabShellWorker JID-877167a0828f402860ff733c INFO: start
2015-09-25_04:21:47.02911 2015-09-25T04:21:47.028Z 1063 TID-duzpw GitlabShellWorker JID-a691790ba46a812860b97e63 INFO: start
2015-09-25_04:21:48.49267 2015-09-25T04:21:48.492Z 1063 TID-dspt0 GitlabShellWorker JID-877167a0828f402860ff733c INFO: done: 1.488 sec
2015-09-25_04:21:48.49541 2015-09-25T04:21:48.495Z 1063 TID-duzpw GitlabShellWorker JID-a691790ba46a812860b97e63 INFO: done: 1.466 sec
2015-09-25_04:22:08.41820 2015-09-25T04:22:08.418Z 1063 TID-duzpw GitlabShellWorker JID-b5ab407360ef2bd515cc1c47 INFO: start
2015-09-25_04:22:08.43116 2015-09-25T04:22:08.431Z 1063 TID-dspt0 GitlabShellWorker JID-ec57ac90f199acc80ef330c6 INFO: start
2015-09-25_04:22:08.44876 2015-09-25T04:22:08.433Z 1063 TID-dp7qo GitlabShellWorker JID-7b346693931a6c77229bd50f INFO: start
2015-09-25_04:22:08.46065 2015-09-25T04:22:08.460Z 1063 TID-dn5l8 GitlabShellWorker JID-1bad73464e4f50a473b6c4c6 INFO: start
2015-09-25_04:22:10.98236 2015-09-25T04:22:10.982Z 1063 TID-duzpw GitlabShellWorker JID-b5ab407360ef2bd515cc1c47 INFO: done: 2.564 sec
2015-09-25_04:22:10.99952 2015-09-25T04:22:10.999Z 1063 TID-dspt0 GitlabShellWorker JID-ec57ac90f199acc80ef330c6 INFO: done: 2.568 sec
2015-09-25_04:22:11.00023 2015-09-25T04:22:11.000Z 1063 TID-dn5l8 GitlabShellWorker JID-1bad73464e4f50a473b6c4c6 INFO: done: 2.54 sec
2015-09-25_04:22:11.02407 2015-09-25T04:22:11.024Z 1063 TID-dp7qo GitlabShellWorker JID-7b346693931a6c77229bd50f INFO: done: 2.591 sec

@ngarner_testout Ok, looks like the same problem. I can't reproduce it on my end. Can you do me a favor and try to tweak the source code to see if this helps? Here's what to do:

Edit /opt/gitlab/embedded/service/gitlab-rails/app/workers/repository_fork_worker.rb (make a backup if you like) from:

    if project.valid_repo?
      ProjectCacheWorker.perform_async(project.id)
      project.import_finish
    else
      project.import_fail
      logger.error("Project #{id} had an invalid repository after fork")
    end

To:

    if project.valid_repo?
      project.import_finish
      project.save!
      ProjectCacheWorker.perform_async(project.id)
    else
      project.import_fail
      logger.error("Project #{id} had an invalid repository after fork")
    end

Run sudo gitlab-ctl restart sidekiq and try again.

Does that help? Please post the Sidekiq logs if there are additional errors. Thanks for your help.

I edited the file and restarted sidekiq as you asked. I was able to fork just one project again afterwards. Here are the lines from the log for the fork that stalled...

2015-09-25_04:54:51.82525 2015-09-25T04:54:51.825Z 3791 TID-l015s GitlabShellWorker JID-2576b6889a653e0965da7611 INFO: start
2015-09-25_04:54:52.08955 2015-09-25T04:54:52.089Z 3791 TID-ktltg GitlabShellWorker JID-74df6c0b0eea92cdc6f6d2b4 INFO: start
2015-09-25_04:54:53.64832 2015-09-25T04:54:53.648Z 3791 TID-l015s GitlabShellWorker JID-2576b6889a653e0965da7611 INFO: done: 1.823 sec
2015-09-25_04:54:53.71684 2015-09-25T04:54:53.716Z 3791 TID-ktltg GitlabShellWorker JID-74df6c0b0eea92cdc6f6d2b4 INFO: done: 1.627 sec
2015-09-25_04:55:04.22428 2015-09-25T04:55:04.224Z 3791 TID-ktltg GitlabShellWorker JID-7d99b30205888df09529383c INFO: start
2015-09-25_04:55:04.35276 2015-09-25T04:55:04.352Z 3791 TID-l015s GitlabShellWorker JID-b6aa4dae4159278ce2af91ff INFO: start
2015-09-25_04:55:05.64719 2015-09-25T04:55:05.647Z 3791 TID-ktltg GitlabShellWorker JID-7d99b30205888df09529383c INFO: done: 1.423 sec
2015-09-25_04:55:05.70371 2015-09-25T04:55:05.703Z 3791 TID-l015s GitlabShellWorker JID-b6aa4dae4159278ce2af91ff INFO: done: 1.351 sec
2015-09-25_04:55:11.62864 2015-09-25T04:55:11.628Z 3791 TID-l015s RepositoryForkWorker JID-8d564c3f4e37181782c65919 INFO: start
2015-09-25_04:55:12.26582 2015-09-25T04:55:12.265Z 3791 TID-ktltg ProjectCacheWorker JID-eba059bd9245300b2afd804a INFO: start
2015-09-25_04:55:12.34036 2015-09-25T04:55:12.340Z 3791 TID-l015s RepositoryForkWorker JID-8d564c3f4e37181782c65919 INFO: done: 0.712 sec
2015-09-25_04:55:12.35764 2015-09-25T04:55:12.357Z 3791 TID-ktltg ProjectCacheWorker JID-eba059bd9245300b2afd804a INFO: done: 0.092 sec

So bizzarre. I can't explain why a 1-second delay would help, or why I can't reproduce the issue at all.

The only way I may have a shot at understand what's going on is to look at the SQL logs during this transaction. If one of you is game, you will have to edit:

/opt/gitlab/embedded/service/gitlab-rails/config/environments/production.rb

Uncomment this line:

  # See everything in the log (default is :info)                                                                                                                                                                       
  config.log_level = :debug

The SQL logs will go into /var/log/gitlab-rails/production.log, so you may want to rename the current one so that you clear out previous data. Restart GitLab completely (sudo gitlab-ctl restart). Then try to fork the repo. We should see updates to import_status like this:

 SQL (2.2ms)  UPDATE "projects" SET "import_status" = $1, "updated_at" = $2 WHERE "projects"."id" = 102  [["import_status", "finished"], ["updated_at", "2015-09-25 05:22:20.679892"]]
  ProjectImportData Load (0.4ms)  SELECT  "project_import_data".* FROM "project_import_data"  WHERE "project_import_data"."project_id" = $1 LIMIT 1  [["project_id", 102]]
   (1.6ms)  COMMIT

mentioned in issue #2572 (closed)

@stanhu See attached file. :)

production.log

@torzech Thanks! Based on those logs, I think it's clear that the database is never updating the import_status field, and I think I finally realized why: Sidekiq is too fast.

Once someone decides to fork a project, it's a race between Rails and the Sidekiq task. If Rails updates the DB with import_status by the time the Sidekiq task completes the fork, things work fine. Otherwise, Sidekiq attempts to mark the import as finished, but since the DB is not in the started state, nothing happens.

I think the simple fix is to edit add_import_job in /opt/gitlab/embedded/service/gitlab-rails/app/models/project.rb and delay it by 2 seconds:

  def add_import_job
    if forked?
      unless RepositoryForkWorker.perform_in(2.seconds, id, forked_from_project.path_with_namespace, self.namespace.path)
        import_fail
      end
    else
      RepositoryImportWorker.perform_in(2.seconds, id)
    end
  end

Can you give that a try and take out the 1-second delay in the worker? You'll probably want to run gitlab-ctl restart to ensure everything is at a good state. Thanks for your help.

@stanhu Yes. That worked. I've forked multiple repositories and everything is OK. Thanks for Your help. :)

mentioned in merge request !1434 (merged)

FYI, looks like other people hit the same issue:

https://github.com/pluginaweek/state_machine/issues/191

Status changed to closed by commit fbe5bf76

mentioned in issue #2775 (closed)

FYI, in the meantime, you can work around the problem of stuck repos by setting the import_status field in the projects table to finished. For example:

$ sudo -u gitlab-psql psql -h /var/opt/gitlab/postgresql -d gitlabhq_production
psql (9.3.5, server 9.2.10)
Type "help" for help.
gitlabhq_production=# UPDATE projects SET import_status = 'finished' where import_status = 'started' and import_url is NULL;

mentioned in commit df1a235f

mentioned in commit fbe5bf76

mentioned in commit f68acbac

FYI, GitLab 8.0.3 contains a fix for this. For those of you running into this issue, would you mind upgrading and verifying that forking now works without getting stuck? Thanks @torzech and @ngarner_testout for all your help.

Hi,

I have installed the version 8.0.3 and the problem for me is not solved. The workaround in the database doesn't work for me, the command for connecting to postgresql fails.

Hello, I am trying to fork gitlab-ce on gitlab.com and I am facing the same problem. Of course, I can't perform the work around above because I have no access to the server. Any help would be greatly appreciated

mentioned in issue #14240 (closed)

Mentioned in commit maxraab/gitlab-ce@df1a235f

[8.0.1] Cannot fork repository

Designs

Child items 0

Activity

Admin message

Admin message

[8.0.1] Cannot fork repository

Activity