Skip to content
Snippets Groups Projects
New issue look: Off

The majority of remote mirrors are not automatically updating

    • Closed Issue created by Drew Blessing @dblessing

    A GitLab.com user recently noted that their remote mirror does not update automatically. It works fine if they trigger a manual update. I did some investigating and see some alarming stats.

    There are 1,782 remote mirrors on GitLab.com:

    irb(main):016:0> RemoteMirror.count
=> 1782

    Of those, only 25 have updated in the past 24 hours. I output one of the partial objects so you can see the last_update_at timestamp showing it has updated today (Nov 30).

    mirrors = RemoteMirror.where(last_update_at: (Time.now - 24.hours)..Time.now)
mirrors.count 
=> 25
mirrors.first
=> #<RemoteMirror id: 2231, project_id: 1997995, url: "...", enabled: true, update_status: "finished", last_update_at: "2016-11-30 16:03:50", last_successful_update_at: "2016-11-30 16:03:50", last_error: nil, ... >

    The rest have not updated recently. Some updated within the past few days, others haven't updated for weeks or months.

    Are these jobs getting triggered? Are they dying in Sidekiq? Is there a bug? I don't see any other reports on the GitLab EE tracker suggesting customers are seeing this in on-prem instances - but that doesn't necessarily mean it's not a bug.

    Designs

    Child items 0

    • No child items are currently open.

    Activity

    • username-removed-274314
      username-removed-274314 @pcarranza ·
      Owner

      @dblessing it doesn't look like we have a lot of gitlab_shell execution in the queue lately which matches with this. Could you get a developer checking in the logs to see if there is activity at all?

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      The queue has been moved to project_mirror, and I do see workers running:

      image

      Is there something else going on here?

    • Drew Blessing
      Drew Blessing @dblessing ·
      Author Owner

      @stanhu I wonder if the workers are dying somehow. That would be weird, since manual update runs work fine.

    • username-removed-274314 Reassigned to @pcarranza

      Reassigned to @pcarranza

    • username-removed-274314
      username-removed-274314 @pcarranza ·
      Owner

      I'm testing with the runbooks as it was broken yet again.

      This morning I had a spike in mirroring jobs, so at least those are running, a different thing is if they are actually doing anything.

    • username-removed-85496
      username-removed-85496 @mike-koch ·

      Just saw this issue after speaking with @gitlab on Twitter about this exact issue. One of my repositories (https://gitlab.com/mike-koch/Mods-for-HESK) is also affected by this issue. Just as @pcarranza said, manual updates of my mirror work fine, while automated updates haven't occurred for about 2 weeks. If there's anything you would like for me to do in order to help solve this issue, let me know; I'd be happy to help in any way possible.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      @mike-koch I peeked at your project. Indeed, the update_status is finished and updated_at on 2016-11-18 02:45:15. I don't see anything in the logs that indicate RepositoryUpdateRemoteMirrorWorker was even scheduled for this project.

      Calling sync on that mirror seems to have moved the mirror into the started state, but I see no signs of it actually trying to run. The updated_at timestamp is current now.

      Listening on the Redis trace, I see it going to the gitlab-shell queue instead of project_mirror:

      1480639720.721018 [0 10.1.0.6:47618] "lpush" "resque:gitlab:queue:gitlab_shell" "{\"class\":\"RepositoryUpdateRemoteMirrorWorker\",\"args\":[8],\"retry\":3,\"queue\":\"gitlab_shell\",\"jid\":\"0fe4e956d290edd3ca7f6a35\",\"created_at\":1480639720.7182343,\"enqueued_at\":1480639720.7183244}"

      I don't see any jobs in that queue, though, and I don't see that job ID in our logs. It's as though something just picked it up and dropped it quietly.

      Still investigating...

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      It looks to me that UpdateAllRemoteMirrorsWorker is actually failing really error on, which might explain why few of these remote mirror jobs are even being run:

      irb(main):031:0> UpdateAllRemoteMirrorsWorker.new.fail_stuck_mirrors!
D, [2016-12-02T07:02:52.845746 #41814] DEBUG -- :   RemoteMirror Load (4.8ms)  SELECT  "remote_mirrors".* FROM "remote_mirrors" WHERE ("remote_mirrors"."update_status" IN ('started')) AND (last_update_at < '2016-12-01 07:02:52.839467' OR (last_update_at IS NULL AND updated_at < '2016-12-01 07:02:52.839710'))  ORDER BY "remote_mirrors"."id" ASC LIMIT 50
D, [2016-12-02T07:02:52.848338 #41814] DEBUG -- :    (0.6ms)  BEGIN
D, [2016-12-02T07:02:52.860694 #41814] DEBUG -- :   Project Load (5.6ms)  SELECT  "projects".* FROM "projects" WHERE "projects"."pending_delete" = $1 AND "projects"."id" = $2  ORDER BY "projects"."id" DESC LIMIT 1  [["pending_delete", "f"], ["id", 1085525]]
D, [2016-12-02T07:02:52.862495 #41814] DEBUG -- :    (0.7ms)  ROLLBACK
NoMethodError: undefined method `import_url' for nil:NilClass
        from /opt/gitlab/embedded/service/gitlab-rails/app/models/remote_mirror.rb:112:in `url_availability'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:182:in `block in conditional'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:504:in `block in call'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:504:in `each'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:504:in `call'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:778:in `_run_validate_callbacks'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activemodel-4.2.7.1/lib/active_model/validations.rb:399:in `run_validations!'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activemodel-4.2.7.1/lib/active_model/validations/callbacks.rb:113:in `block in run_validations!'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:117:in `call'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505:in `call'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/state_machines-activemodel-0.4.0/lib/state_machines/integrations/active_model.rb:400:in `block in around_validation'
... 77 levels...
        from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/metrics/instrumentation.rb:157:in `mark_as_failed'
        from /opt/gitlab/embedded/service/gitlab-rails/app/workers/update_all_remote_mirrors_worker.rb:13:in `block in fail_stuck_mirrors!'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/relation/batches.rb:51:in `block (2 levels) in find_each'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/relation/batches.rb:51:in `each'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/relation/batches.rb:51:in `block in find_each'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/relation/batches.rb:124:in `find_in_batches'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/relation/batches.rb:50:in `find_each'
        from /opt/gitlab/embedded/service/gitlab-rails/app/workers/update_all_remote_mirrors_worker.rb:12:in `fail_stuck_mirrors!'
        from (irb):31
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/console.rb:110:in `start'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/console.rb:9:in `start'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:68:in `console'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
        from /opt/gitlab/embedded/service/gem/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands.rb:17:in `<top (required)>'
        from bin/rails:9:in `require'
        from bin/rails:9:in `<main>'

      Looks related to https://gitlab.com/gitlab-org/gitlab-ce/issues/23650.

      https://log.gitlap.com/goto/194c19ae3f704fbe0e26f3a85bdf34c2

      Edited by Stan Hu
    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      Yep, that project is in pending_delete.

    • username-removed-274314
      username-removed-274314 @pcarranza ·
      Owner

      @stanhu can we get development to take a look?

      Runbooks haven't had any automatic mirror update in the last 15hs, which points to: these things are not running.

      Screen_Shot_2016-12-02_at_08.58.33

    • username-removed-128633
      username-removed-128633 @rymai ·
      Maintainer

      Fix by @stanhu is at gitlab-org/gitlab-ee!938.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      I think it is working now.

      irb(main):018:0> mirrors = RemoteMirror.where(last_update_at: (Time.now - 24.hours)..Time.now); mirrors.count
=> 1657
    • Stan Hu closed

      closed

    • Drew Blessing
      Drew Blessing @dblessing ·
      Author Owner

      Thanks all!

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      We are still seeing some users complain their mirrors aren't running: https://gitlab.com/gitlab-com/support-forum/issues/1287, so I'll reopen this issue.

    • Stan Hu reopened

      reopened

    • Rubén Dávila
      Rubén Dávila @rdavila ·
      Maintainer

      I think sync of local mirrors are working fine for now:

      irb(main):002:0> Project.where(mirror: true).count
=> 13636
irb(main):003:0> Project.where('mirror_last_update_at >= ? AND mirror = ?', 24.hours.ago, true).count
=> 13089

      The failed syncs are mostly due to two errors: The mirror user is not allowed to push code to all branches on this project. and The mirror update took too long to complete.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      Thanks @rdavila!

    • Stan Hu closed

      closed

    Please register or sign in to reply