qa/specs/features/api/3_create/gitaly/automatic_failover_and_recovery_spec.rb:69
Summary
https://gitlab.com/gitlab-org/gitlab-qa-mirror/-/jobs/690712032
Stack trace
2) Create Gitaly automatic failover and manual recovery when recovering from dataloss after failover allows reconciliation
Failure/Error: expect(praefect_manager.replicated?(project.id)).to be false
expected false
got true
# ./qa/specs/features/api/3_create/gitaly/automatic_failover_and_recovery_spec.rb:75:in `block (4 levels) in <module:QA>'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:123:in `block in run'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:110:in `loop'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:110:in `run'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
# ./spec/spec_helper.rb:69:in `block (2 levels) in <top (required)>'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:123:in `block in run'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:110:in `loop'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:110:in `run'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
# /usr/local/bundle/gems/rspec-retry-0.6.1/lib/rspec/retry.rb:37:in `block (2 levels) in setup'
# ./qa/specs/runner.rb:71:in `perform'
# ./qa/scenario/template.rb:10:in `block in perform'
# ./qa/scenario/template.rb:8:in `tap'
# ./qa/scenario/template.rb:8:in `perform'
# ./qa/scenario/template.rb:35:in `perform'
# ./qa/scenario/template.rb:10:in `block in perform'
# ./qa/scenario/template.rb:8:in `tap'
# ./qa/scenario/template.rb:8:in `perform'
# ./qa/scenario/bootable.rb:28:in `launch!'
Debug output:
when recovering from dataloss after failover
D, [2020-08-18T04:24:33.143577 #23] DEBUG -- :
Starting test: Create Gitaly automatic failover and manual recovery when recovering from dataloss after failover allows reconciliation
Executing `docker start gitaly1`
gitaly1
Executing `docker exec praefect bash -c '/opt/gitlab/embedded/bin/praefect -config /var/opt/gitlab/praefect/config.toml dataloss'`
D, [2020-08-18T04:24:34.620641 #23] DEBUG -- : Virtual storage: default
D, [2020-08-18T04:24:34.622178 #23] DEBUG -- : Primary: gitaly3
I, [2020-08-18T04:24:34.624499 #23] INFO -- : Waiting for health check on gitaly3
D, [2020-08-18T04:24:34.625107 #23] DEBUG -- : with wait_until: max_duration: 60; reload_page: ; sleep_interval: 1; raise_on_failure: true
Executing `docker exec gitaly3 bash -c 'cat /var/log/gitlab/gitaly/current'`
D, [2020-08-18T04:24:34.814531 #23] DEBUG -- : {"level":"info","msg":"Wrapper started","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:24:34.815831 #23] DEBUG -- : {"level":"info","msg":"finding gitaly","pid_file":"/var/opt/gitlab/gitaly/gitaly.pid","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:24:34.816589 #23] DEBUG -- : {"level":"info","msg":"spawning a process","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:24:34.817663 #23] DEBUG -- : {"gitaly":292,"level":"info","msg":"monitoring gitaly","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:24:34.823267 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting Gitaly" version="Gitaly, version 13.3.0-rc5-3-gc6e8f5d5"
D, [2020-08-18T04:24:34.823934 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=warning msg="git path not configured. Using default path resolution" resolvedPath=/opt/gitlab/embedded/bin/git
D, [2020-08-18T04:24:34.824741 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="clearing disk cache object folder" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:24:34.825285 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="moving disk cache object folder to /var/opt/gitlab/git-data/repositories/+gitaly/tmp/diskcache987778997" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:24:34.825854 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting file walker for /var/opt/gitlab/git-data/repositories/+gitaly/cache" path=/var/opt/gitlab/git-data/repositories/+gitaly/cache
D, [2020-08-18T04:24:34.826371 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting file walker for /var/opt/gitlab/git-data/repositories/+gitaly/state" path=/var/opt/gitlab/git-data/repositories/+gitaly/state
D, [2020-08-18T04:24:34.826956 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="cleared all cache object files in /var/opt/gitlab/git-data/repositories/+gitaly/tmp/diskcache987778997 after 417.912µs" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:24:34.828802 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly1","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:24:34.829470 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly2","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:24:34.830158 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly3","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:24:34.830901 #23] DEBUG -- : {"address":"/var/opt/gitlab/gitaly/gitaly.socket","level":"info","msg":"listening at unix address","time":"2020-08-18T04:17:38.533Z"}
D, [2020-08-18T04:24:34.831524 #23] DEBUG -- : {"address":"/var/opt/gitlab/gitaly/internal_sockets/internal.sock","level":"info","msg":"listening at unix address","time":"2020-08-18T04:17:38.543Z"}
D, [2020-08-18T04:24:34.832227 #23] DEBUG -- : {"address":"0.0.0.0:8075","level":"info","msg":"listening at tcp address","time":"2020-08-18T04:17:38.543Z"}
D, [2020-08-18T04:24:34.833008 #23] DEBUG -- : {"address":"0.0.0.0:9236","level":"info","msg":"starting prometheus listener","time":"2020-08-18T04:17:38.592Z"}
D, [2020-08-18T04:24:34.833731 #23] DEBUG -- : {"level":"info","msg":"starting RSS monitor","supervisor.name":"gitaly-ruby.1","supervisor.rss_threshold":209715200,"time":"2020-08-18T04:17:38.616Z"}
D, [2020-08-18T04:24:34.834414 #23] DEBUG -- : {"level":"info","msg":"starting RSS monitor","supervisor.name":"gitaly-ruby.0","supervisor.rss_threshold":209715200,"time":"2020-08-18T04:17:38.617Z"}
D, [2020-08-18T04:24:34.840042 #23] DEBUG -- : {"level":"warning","msg":"spawned","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.1"],"supervisor.name":"gitaly-ruby.1","supervisor.pid":311,"time":"2020-08-18T04:17:38.631Z"}
D, [2020-08-18T04:24:34.841137 #23] DEBUG -- : {"level":"warning","msg":"spawned","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.0"],"supervisor.name":"gitaly-ruby.0","supervisor.pid":314,"time":"2020-08-18T04:17:38.653Z"}
D, [2020-08-18T04:24:34.845525 #23] DEBUG -- : {"level":"info","msg":"PID 311 BUNDLE_GEMFILE=/opt/gitlab/embedded/service/gitaly-ruby/Gemfile","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.1"],"supervisor.name":"gitaly-ruby.1","time":"2020-08-18T04:17:41.593Z"}
D, [2020-08-18T04:24:34.846177 #23] DEBUG -- : {"level":"info","msg":"PID 314 BUNDLE_GEMFILE=/opt/gitlab/embedded/service/gitaly-ruby/Gemfile","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.0"],"supervisor.name":"gitaly-ruby.0","time":"2020-08-18T04:17:41.662Z"}
D, [2020-08-18T04:24:34.846815 #23] DEBUG -- : {"grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"unknown","grpc.method":"Check","grpc.request.deadline":"2020-08-18T04:18:05Z","grpc.request.fullMethod":"/grpc.health.v1.Health/Check","grpc.service":"grpc.health.v1.Health","grpc.start_time":"2020-08-18T04:18:04Z","grpc.time_ms":0.059,"level":"info","msg":"finished unary call with code OK","peer.address":"172.19.0.6:54822","pid":292,"span.kind":"server","system":"grpc","time":"2020-08-18T04:18:04.194Z"}
D, [2020-08-18T04:24:34.857275 #23] DEBUG -- : ended wait_until
D, [2020-08-18T04:24:34.857826 #23] DEBUG -- : with retry_until: max_attempts: 3; reload_page: ; sleep_interval: 0; raise_on_failure: false; retry_on_exception: false
D, [2020-08-18T04:24:34.858287 #23] DEBUG -- : Attempt number 1
D, [2020-08-18T04:24:34.858719 #23] DEBUG -- : with wait_until: max_duration: 60; reload_page: ; sleep_interval: 1; raise_on_failure: true
Executing `docker exec gitlab-gitaly-cluster bash -c 'gitlab-rake "gitlab:praefect:replicas[5]"'`
D, [2020-08-18T04:25:24.839824 #23] DEBUG -- : Something went wrong when getting replicas.
D, [2020-08-18T04:25:24.888119 #23] DEBUG -- : Attempt number 2
D, [2020-08-18T04:25:24.888316 #23] DEBUG -- : with wait_until: max_duration: 60; reload_page: ; sleep_interval: 1; raise_on_failure: true
Executing `docker exec gitlab-gitaly-cluster bash -c 'gitlab-rake "gitlab:praefect:replicas[5]"'`
D, [2020-08-18T04:25:55.830765 #23] DEBUG -- :
D, [2020-08-18T04:25:55.830903 #23] DEBUG -- : Project name | gitaly3 (primary) | gitaly1 | gitaly2
D, [2020-08-18T04:25:55.830948 #23] DEBUG -- : ----------------------------------------------------------------------------------------------------------------------------------------------------------------
D, [2020-08-18T04:25:55.831298 #23] DEBUG -- : gitaly_cluster-e4983bc25a505c3f | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5 | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5 | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5
D, [2020-08-18T04:25:55.877195 #23] DEBUG -- : ended retry_until
WARN: Screenshot could not be saved. `page.current_path` is empty.
D, [2020-08-18T04:25:55.900138 #23] DEBUG -- :
Starting test: Create Gitaly automatic failover and manual recovery when recovering from dataloss after failover allows reconciliation
Executing `docker start gitaly1`
gitaly1
Executing `docker exec praefect bash -c '/opt/gitlab/embedded/bin/praefect -config /var/opt/gitlab/praefect/config.toml dataloss'`
D, [2020-08-18T04:25:56.266183 #23] DEBUG -- : Virtual storage: default
D, [2020-08-18T04:25:56.266617 #23] DEBUG -- : Primary: gitaly3
I, [2020-08-18T04:25:56.296112 #23] INFO -- : Waiting for health check on gitaly3
D, [2020-08-18T04:25:56.296761 #23] DEBUG -- : with wait_until: max_duration: 60; reload_page: ; sleep_interval: 1; raise_on_failure: true
Executing `docker exec gitaly3 bash -c 'cat /var/log/gitlab/gitaly/current'`
D, [2020-08-18T04:25:56.430206 #23] DEBUG -- : {"level":"info","msg":"Wrapper started","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:25:56.430479 #23] DEBUG -- : {"level":"info","msg":"finding gitaly","pid_file":"/var/opt/gitlab/gitaly/gitaly.pid","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:25:56.430585 #23] DEBUG -- : {"level":"info","msg":"spawning a process","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:25:56.430752 #23] DEBUG -- : {"gitaly":292,"level":"info","msg":"monitoring gitaly","time":"2020-08-18T04:17:34Z","wrapper":287}
D, [2020-08-18T04:25:56.430842 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting Gitaly" version="Gitaly, version 13.3.0-rc5-3-gc6e8f5d5"
D, [2020-08-18T04:25:56.430973 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=warning msg="git path not configured. Using default path resolution" resolvedPath=/opt/gitlab/embedded/bin/git
D, [2020-08-18T04:25:56.431060 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="clearing disk cache object folder" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:25:56.431124 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="moving disk cache object folder to /var/opt/gitlab/git-data/repositories/+gitaly/tmp/diskcache987778997" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:25:56.431230 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting file walker for /var/opt/gitlab/git-data/repositories/+gitaly/cache" path=/var/opt/gitlab/git-data/repositories/+gitaly/cache
D, [2020-08-18T04:25:56.431294 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="Starting file walker for /var/opt/gitlab/git-data/repositories/+gitaly/state" path=/var/opt/gitlab/git-data/repositories/+gitaly/state
D, [2020-08-18T04:25:56.431347 #23] DEBUG -- : time="2020-08-18T04:17:35Z" level=info msg="cleared all cache object files in /var/opt/gitlab/git-data/repositories/+gitaly/tmp/diskcache987778997 after 417.912µs" path=/var/opt/gitlab/git-data/repositories
D, [2020-08-18T04:25:56.431404 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly1","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:25:56.431510 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly2","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:25:56.431632 #23] DEBUG -- : {"level":"info","msg":"finished tempdir cleaner walk","storage":"gitaly3","time":"2020-08-18T04:17:38.532Z","time_ms":0}
D, [2020-08-18T04:25:56.431692 #23] DEBUG -- : {"address":"/var/opt/gitlab/gitaly/gitaly.socket","level":"info","msg":"listening at unix address","time":"2020-08-18T04:17:38.533Z"}
D, [2020-08-18T04:25:56.431742 #23] DEBUG -- : {"address":"/var/opt/gitlab/gitaly/internal_sockets/internal.sock","level":"info","msg":"listening at unix address","time":"2020-08-18T04:17:38.543Z"}
D, [2020-08-18T04:25:56.431800 #23] DEBUG -- : {"address":"0.0.0.0:8075","level":"info","msg":"listening at tcp address","time":"2020-08-18T04:17:38.543Z"}
D, [2020-08-18T04:25:56.433966 #23] DEBUG -- : {"address":"0.0.0.0:9236","level":"info","msg":"starting prometheus listener","time":"2020-08-18T04:17:38.592Z"}
D, [2020-08-18T04:25:56.434060 #23] DEBUG -- : {"level":"info","msg":"starting RSS monitor","supervisor.name":"gitaly-ruby.1","supervisor.rss_threshold":209715200,"time":"2020-08-18T04:17:38.616Z"}
D, [2020-08-18T04:25:56.434634 #23] DEBUG -- : {"level":"info","msg":"starting RSS monitor","supervisor.name":"gitaly-ruby.0","supervisor.rss_threshold":209715200,"time":"2020-08-18T04:17:38.617Z"}
D, [2020-08-18T04:25:56.434832 #23] DEBUG -- : {"level":"warning","msg":"spawned","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.1"],"supervisor.name":"gitaly-ruby.1","supervisor.pid":311,"time":"2020-08-18T04:17:38.631Z"}
D, [2020-08-18T04:25:56.435129 #23] DEBUG -- : {"level":"warning","msg":"spawned","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.0"],"supervisor.name":"gitaly-ruby.0","supervisor.pid":314,"time":"2020-08-18T04:17:38.653Z"}
D, [2020-08-18T04:25:56.435414 #23] DEBUG -- : {"level":"info","msg":"PID 311 BUNDLE_GEMFILE=/opt/gitlab/embedded/service/gitaly-ruby/Gemfile","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.1"],"supervisor.name":"gitaly-ruby.1","time":"2020-08-18T04:17:41.593Z"}
D, [2020-08-18T04:25:56.435757 #23] DEBUG -- : {"level":"info","msg":"PID 314 BUNDLE_GEMFILE=/opt/gitlab/embedded/service/gitaly-ruby/Gemfile","supervisor.args":["bundle","exec","bin/ruby-cd","/var/opt/gitlab/gitaly","/opt/gitlab/embedded/service/gitaly-ruby/bin/gitaly-ruby","292","/var/opt/gitlab/gitaly/internal_sockets/ruby.0"],"supervisor.name":"gitaly-ruby.0","time":"2020-08-18T04:17:41.662Z"}
D, [2020-08-18T04:25:56.436027 #23] DEBUG -- : {"grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"unknown","grpc.method":"Check","grpc.request.deadline":"2020-08-18T04:18:05Z","grpc.request.fullMethod":"/grpc.health.v1.Health/Check","grpc.service":"grpc.health.v1.Health","grpc.start_time":"2020-08-18T04:18:04Z","grpc.time_ms":0.059,"level":"info","msg":"finished unary call with code OK","peer.address":"172.19.0.6:54822","pid":292,"span.kind":"server","system":"grpc","time":"2020-08-18T04:18:04.194Z"}
D, [2020-08-18T04:25:56.444730 #23] DEBUG -- : ended wait_until
D, [2020-08-18T04:25:56.445028 #23] DEBUG -- : with retry_until: max_attempts: 3; reload_page: ; sleep_interval: 0; raise_on_failure: false; retry_on_exception: false
D, [2020-08-18T04:25:56.445119 #23] DEBUG -- : Attempt number 1
D, [2020-08-18T04:25:56.445925 #23] DEBUG -- : with wait_until: max_duration: 60; reload_page: ; sleep_interval: 1; raise_on_failure: true
Executing `docker exec gitlab-gitaly-cluster bash -c 'gitlab-rake "gitlab:praefect:replicas[5]"'`
D, [2020-08-18T04:26:25.644242 #23] DEBUG -- :
D, [2020-08-18T04:26:25.644971 #23] DEBUG -- : Project name | gitaly3 (primary) | gitaly1 | gitaly2
D, [2020-08-18T04:26:25.645311 #23] DEBUG -- : ----------------------------------------------------------------------------------------------------------------------------------------------------------------
D, [2020-08-18T04:26:25.645657 #23] DEBUG -- : gitaly_cluster-e4983bc25a505c3f | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5 | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5 | a86050c72b9de6508d68d0bc0fa80f8fce3e8ba5
D, [2020-08-18T04:26:25.690157 #23] DEBUG -- : ended retry_until
WARN: Screenshot could not be saved. `page.current_path` is empty.
allows reconciliation (FAILED - 2)
1st Try error in ./qa/specs/features/api/3_create/gitaly/automatic_failover_and_recovery_spec.rb:69:
expected false
got true
RSpec::Retry: 2nd try ./qa/specs/features/api/3_create/gitaly/automatic_failover_and_recovery_spec.rb:69
Screenshot / HTML page
Possible fixes
Edited by Rémy Coutable