Skip to content
Snippets Groups Projects

rspec background_migration pg14 5/10

Passed Started by
Eduardo Sanz García
@eduardosanz
Log timestamps in UTC.
117:44:29Running with gitlab-runner 17.4.0~pre.110.g27400594 (27400594)
217:44:29 on blue-2.private.runners-manager.gitlab.com/gitlab.com/gitlab-org QvBVRoXM, system ID: s_49b872f8ccf6
317:44:29 feature flags: FF_NETWORK_PER_BUILD:true, FF_TIMESTAMPS:true
417:44:29Resolving secrets
5 17:44:29 Preparing the "docker+machine" executor 00:25
617:44:29Using Docker executor with image registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14:rubygems-3.5-git-2.45-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 ...
717:44:31Starting service registry.gitlab.com/gitlab-org/gitlab-build-images:postgres-14-pgvector-0.4.1...
817:44:31Authenticating with credentials from job payload (GitLab Registry)
917:44:31Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images:postgres-14-pgvector-0.4.1 ...
1017:44:38Using docker image sha256:82f132c22567f8ce17cc132c14b2f9aa3eaf9bb5424d91c2d966912433f0257d for registry.gitlab.com/gitlab-org/gitlab-build-images:postgres-14-pgvector-0.4.1 with digest registry.gitlab.com/gitlab-org/gitlab-build-images@sha256:c55e1364ee4327b244a9cfa1750f19feea14fc774eaf792b725967d146eb45f5 ...
1117:44:42WARNING: Service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 is already created. Ignoring.
1217:44:42WARNING: Service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 is already created. Ignoring.
1317:44:42Starting service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12...
1417:44:42Authenticating with credentials from job payload (GitLab Registry)
1517:44:42Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 ...
1617:44:46Using docker image sha256:5c5ba5b83d6c60cb0b225bd670b7a43be8c238cc72347d24af57e5027c3648f3 for registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 with digest registry.gitlab.com/gitlab-org/gitlab-build-images@sha256:46aceab84c42d0e819c8e7940f2f98ce9e184785cd7b22d95872024a35f52407 ...
1717:44:47Starting service redis:6.2-alpine...
1817:44:47Pulling docker image redis:6.2-alpine ...
1917:44:50Using docker image sha256:ec1b0a84ddf9124276ac189cc4d98ef28f0aea95ebd148d9e4c18b28928dd999 for redis:6.2-alpine with digest redis@sha256:2ba50e1ac3a0ea17b736ce9db2b0a9f6f8b85d4c27d5f5accc6a416d8f42c6d5 ...
2017:44:51Waiting for services to be up and running (timeout 30 seconds)...
2117:44:53Authenticating with credentials from job payload (GitLab Registry)
2217:44:53Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14:rubygems-3.5-git-2.45-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 ...
2317:44:54Using docker image sha256:31e981de8a825083695845b07ca34c01ce0f1c5b3e7d9e89e52e5b77c0df04a5 for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14:rubygems-3.5-git-2.45-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 with digest registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14@sha256:a5a9db043a920dcc296b68cfbed0958437128c3e391789aea0af2ac25d2a36db ...
24 17:44:54 Preparing environment 00:00
2517:44:54Running on runner-qvbvroxm-project-278964-concurrent-0 via runner-qvbvroxm-private-1731001288-2ec29a66...
26 17:44:54 Getting source from Git repository 00:01
2717:44:54Skipping Git repository setup
2817:44:54Skipping Git checkout
2917:44:54Skipping Git submodules setup
30 17:44:55 Restoring cache 00:15
3117:44:55Checking cache for ruby-gems-debian-bookworm-ruby-3.2.5-gemfile-Gemfile-20...
3217:44:55Downloading cache from https://storage.googleapis.com/gitlab-com-runners-cache/project/278964/ruby-gems-debian-bookworm-ruby-3.2.5-gemfile-Gemfile-20 ETag="7ab11bf81aafd8042bedf88f6f2e321b"
3317:45:05Successfully extracted cache
34 17:45:10 Downloading artifacts 00:42
3517:45:10Downloading artifacts for clone-gitlab-repo (8298975602)...
3617:45:15Downloading artifacts from coordinator... ok host=storage.googleapis.com id=8298975602 responseStatus=200 OK token=glcbt-66
3717:45:15WARNING: Part of .git directory is on the list of files to extract
3817:45:15WARNING: This may introduce unexpected problems
3917:45:27Downloading artifacts for compile-test-assets (8298975678)...
4017:45:30Downloading artifacts from coordinator... ok host=storage.googleapis.com id=8298975678 responseStatus=200 OK token=glcbt-66
4117:45:34Downloading artifacts for detect-tests (8298975687)...
4217:45:34Downloading artifacts from coordinator... ok host=storage.googleapis.com id=8298975687 responseStatus=200 OK token=glcbt-66
4317:45:34Downloading artifacts for retrieve-tests-metadata (8298975696)...
4417:45:35Downloading artifacts from coordinator... ok host=storage.googleapis.com id=8298975696 responseStatus=200 OK token=glcbt-66
4517:45:35Downloading artifacts for setup-test-env (8298975682)...
4617:45:40Downloading artifacts from coordinator... ok host=storage.googleapis.com id=8298975682 responseStatus=200 OK token=glcbt-66
47 17:45:52 Executing "step_script" stage of the job script
4817:45:52Using docker image sha256:31e981de8a825083695845b07ca34c01ce0f1c5b3e7d9e89e52e5b77c0df04a5 for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14:rubygems-3.5-git-2.45-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 with digest registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.5-golang-1.23-rust-1.73-node-20.12-postgresql-14@sha256:a5a9db043a920dcc296b68cfbed0958437128c3e391789aea0af2ac25d2a36db ...
4917:45:53$ echo $FOSS_ONLY
5017:45:53$ [ "$FOSS_ONLY" = "1" ] && rm -rf ee/ qa/spec/ee/ qa/qa/specs/features/ee/ qa/qa/ee/ qa/qa/ee.rb
5117:45:53$ export GOPATH=$CI_PROJECT_DIR/.go
5217:45:53$ mkdir -p $GOPATH
5317:45:53$ source scripts/utils.sh
5417:45:53$ log_disk_usage "true"
5517:45:54*******************************************************
5617:45:54This runner currently has 80G free disk space.
5717:45:54*******************************************************
58 17:45:54 Disk usage detail 00:00
5917:45:54df -h
6017:45:54Filesystem Size Used Avail Use% Mounted on
6117:45:54overlay 95G 15G 80G 16% /
6217:45:54tmpfs 64M 0 64M 0% /dev
6317:45:54shm 64M 0 64M 0% /dev/shm
6417:45:54/dev/sda1 95G 15G 80G 16% /cache
6517:45:54tmpfs 3.9G 0 3.9G 0% /sys/devices/virtual/dmi/id
6617:45:54du -h -d 1
6717:45:547.4M ./workhorse
6817:45:54148K ./bin
6917:45:541.2M ./.gitlab
7017:45:54176M ./.git
7117:45:544.0K ./builds
7217:45:5428M ./lib
7317:45:548.0K ./.vscode
7417:45:54560K ./storybook
7517:45:5420K ./log
7617:45:541.8M ./data
7717:45:5411M ./qa
7817:45:543.2M ./.rubocop_todo
7917:45:54817M ./vendor
8017:45:54681M ./public
8117:45:5460M ./doc
8217:45:54472K ./danger
8317:45:5440K ./rspec
8417:45:54548K ./tooling
8517:45:54145M ./ee
8617:45:541.3M ./knapsack
8717:45:54300K ./patches
8817:45:544.3M ./changelogs
8917:45:5420K ./haml_lint
9017:45:5428K ./metrics_server
9117:45:5496K ./keeps
9217:45:5436K ./shared
9317:45:5444K ./generator_templates
9417:45:541.3M ./scripts
9517:45:54764M ./tmp
9617:45:54127M ./spec
9717:45:5420K ./file_hooks
9817:45:5432K ./crystalball
9917:45:5416K ./sidekiq_cluster
10017:45:5417M ./gems
10117:45:541.2M ./fixtures
10217:45:54968K ./rubocop
10317:45:544.0K ./.go
10417:45:5432M ./db
10517:45:5412K ./.github
10617:45:54129M ./locale
10717:45:5420M ./config
10817:45:5481M ./app
10917:45:5420K ./.lefthook
11017:45:543.1G .
11117:45:54$ source scripts/prepare_build.sh
112 17:45:54 Installing gems 00:21
14317:46:15Using decomposed database config (config/database.yml.decomposed-postgresql)
14417:46:15Geo DB won't be set up.
14517:46:15Embedding DB won't be set up.
146 17:46:15 Setting up DBs 01:29
15917:47:44$ source ./scripts/rspec_helpers.sh
16017:47:44$ run_timed_command "gem install knapsack --no-document"
16117:47:44$ gem install knapsack --no-document
16217:47:45Successfully installed knapsack-4.0.0
16317:47:451 gem installed
16417:47:44==> 'gem install knapsack --no-document' succeeded in 1 seconds.
16517:47:45$ section_start "gitaly-test-spawn" "Spawning Gitaly"; scripts/gitaly-test-spawn; section_end "gitaly-test-spawn"
166 17:47:45 Spawning Gitaly 00:05
17017:47:50$ export RSPEC_SKIPPED_TESTS_REPORT_PATH="rspec/skipped_tests-${CI_JOB_ID}.txt"
17117:47:50$ export RSPEC_RETRIED_TESTS_REPORT_PATH="rspec/retried_tests-${CI_JOB_ID}.txt"
17217:47:50$ tooling/bin/create_job_metrics_file || true
17317:47:53[job-metrics] Creating the job metrics file for the CI/CD job.
17417:47:53$ rspec_section rspec_parallelized_job "--fail-fast=${RSPEC_FAIL_FAST_THRESHOLD} --tag ~quarantine --tag ~zoekt --tag ~click_house"
175 17:47:53 RSpec 51:11
17617:47:53[17:47:53] Starting rspec_parallelized_job
17717:47:45RETRY_FAILED_TESTS_IN_NEW_PROCESS: true
17817:47:53KNAPSACK_GENERATE_REPORT: true
17917:47:53FLAKY_RSPEC_GENERATE_REPORT: true
18017:47:53KNAPSACK_TEST_FILE_PATTERN: spec/{lib/gitlab/background_migration,lib/ee/gitlab/background_migration}{,/**/}*_spec.rb
18117:47:53KNAPSACK_LOG_LEVEL: debug
18217:47:53KNAPSACK_REPORT_PATH: knapsack/rspec_background_migration_pg14_5_10_278964_report.json
18317:47:53FLAKY_RSPEC_SUITE_REPORT_PATH: rspec/flaky/report-suite.json
18417:47:53FLAKY_RSPEC_REPORT_PATH: rspec/flaky/all_rspec_background_migration_pg14_5_10_278964_report.json
18517:47:53NEW_FLAKY_RSPEC_REPORT_PATH: rspec/flaky/new_rspec_background_migration_pg14_5_10_278964_report.json
18617:47:53RSPEC_SKIPPED_TESTS_REPORT_PATH: rspec/skipped_tests-8298976130.txt
18717:47:53CRYSTALBALL:
18817:47:53RSPEC_TESTS_MAPPING_ENABLED:
18917:47:53RSPEC_TESTS_FILTER_FILE:
19017:47:53Shell set options (set -o) enabled:
19117:47:53braceexpand on
19217:47:54hashall on
19317:47:54interactive-comments on
19417:47:54pipefail on
19517:48:00Knapsack report generator started!
19617:47:54/builds/gitlab-org/gitlab/vendor/ruby/3.2.0/gems/io-event-1.6.5/lib/io/event/support.rb:27: warning: IO::Buffer is experimental and both the Ruby and C interface may change in the future!
19717:49:00DEPRECATION WARNING: Support for Rails versions < 7.1 is deprecated and will be removed from ViewComponent 4.0.0 (ViewComponent v4 will remove support for Rails versions < 7.1 no earlier than April 1, 2025) (called from <top (required)> at /builds/gitlab-org/gitlab/config/environment.rb:7)
19817:49:12warning: parser/current is loading parser/ruby32, which recognizes 3.2.6-compliant syntax, but you are running 3.2.5.
19917:49:12Please see https://github.com/whitequark/parser#compatibility-with-ruby-mri.
20017:49:18Run options: exclude {:quarantine=>true, :zoekt=>true, :click_house=>true}
20117:49:18# [RSpecRunTime] Starting RSpec timer...
20217:49:18[TEST PROF INFO] EventProf enabled (sql.active_record)
20317:49:18unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
20417:49:18unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
20517:49:29Test environment set up in 3.254177208 seconds
20617:49:29# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb. Expected to take 2 minutes 53.41 seconds.
20717:49:29Gitlab::BackgroundMigration::BackfillVulnerabilityReadsClusterAgent
20817:51:20 #filter_batch
20917:51:43 pick only vulnerability reads where report_type = 7
21017:51:43 #perform
21117:52:01 backfills `casted_cluster_agent_id` for the selected records
21217:52:17 tracks timings of queries
21317:52:18# [RSpecRunTime] RSpec elapsed time: 2 minutes 59.36 seconds. Current RSS: ~1237M. Threads: 1. load average: 1.23 1.17 0.72 1/266 390
21417:52:18.
21517:52:20I, [2024-11-07T17:52:20.893019 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
21617:52:41I, [2024-11-07T17:52:41.830818 #345] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
21717:52:43INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
21817:52:43INFO: analyzing "public.ci_pipeline_variables"
21917:52:43INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
22017:52:43I, [2024-11-07T17:52:43.470097 #345] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
22117:52:43I, [2024-11-07T17:52:43.471225 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
22217:52:43I, [2024-11-07T17:52:43.472258 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
22317:52:45INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
22417:52:45INFO: analyzing "public.ci_pipeline_variables"
22517:52:45INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
22617:52:50INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
22717:52:50INFO: analyzing "public.ci_job_artifacts"
22817:52:50INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
22917:52:50I, [2024-11-07T17:52:50.087029 #345] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
23017:52:50I, [2024-11-07T17:52:50.088332 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
23117:52:50I, [2024-11-07T17:52:50.089163 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
23217:52:53INFO: analyzing "public.p_ci_stages" inheritance tree
23317:52:53INFO: analyzing "public.ci_stages"
23417:52:53INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
23517:52:53I, [2024-11-07T17:52:53.418892 #345] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
23617:52:53I, [2024-11-07T17:52:53.428270 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
23717:52:53I, [2024-11-07T17:52:53.430438 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
23817:52:54I, [2024-11-07T17:52:54.753421 #345] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
23917:53:01I, [2024-11-07T17:53:01.453325 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
24017:53:15I, [2024-11-07T17:53:15.489890 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
24117:53:15I, [2024-11-07T17:53:15.491038 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
24217:53:15I, [2024-11-07T17:53:15.491777 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
24317:53:27I, [2024-11-07T17:53:27.647179 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
24417:53:34I, [2024-11-07T17:53:34.731277 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
24517:53:42I, [2024-11-07T17:53:42.771434 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
24617:53:45I, [2024-11-07T17:53:45.353043 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
24717:53:49INFO: analyzing "public.p_ci_pipelines" inheritance tree
24817:53:49INFO: analyzing "public.ci_pipelines"
24917:53:49INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
25017:53:49I, [2024-11-07T17:53:49.129362 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
25117:53:49I, [2024-11-07T17:53:49.130518 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
25217:53:49I, [2024-11-07T17:53:49.131422 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
25317:53:55I, [2024-11-07T17:53:55.237762 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
25417:54:05I, [2024-11-07T17:54:05.912018 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
25517:54:05I, [2024-11-07T17:54:05.913474 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
25617:54:05I, [2024-11-07T17:54:05.914331 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
25717:54:05I, [2024-11-07T17:54:05.917848 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
25817:54:05I, [2024-11-07T17:54:05.919027 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
25917:54:05I, [2024-11-07T17:54:05.919870 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
26017:54:05I, [2024-11-07T17:54:05.923644 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
26117:54:05I, [2024-11-07T17:54:05.924732 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
26217:54:05I, [2024-11-07T17:54:05.925669 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
26317:54:05I, [2024-11-07T17:54:05.929118 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
26417:54:05I, [2024-11-07T17:54:05.930529 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
26517:54:05I, [2024-11-07T17:54:05.931368 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
26617:54:06I, [2024-11-07T17:54:06.938557 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
26717:54:06I, [2024-11-07T17:54:06.939903 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
26817:54:06I, [2024-11-07T17:54:06.940882 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
26917:54:06I, [2024-11-07T17:54:06.944642 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
27017:54:06I, [2024-11-07T17:54:06.945850 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
27117:54:06I, [2024-11-07T17:54:06.946734 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
27217:54:06I, [2024-11-07T17:54:06.950524 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
27317:54:06I, [2024-11-07T17:54:06.951726 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
27417:54:06I, [2024-11-07T17:54:06.952660 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
27517:54:06I, [2024-11-07T17:54:06.956711 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
27617:54:06I, [2024-11-07T17:54:06.957871 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
27717:54:06I, [2024-11-07T17:54:06.958724 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
27817:54:24# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb. It took 4 minutes 55.26 seconds. Expected to take 2 minutes 53.41 seconds.
27917:54:24# [RSpecRunTime] RSpec elapsed time: 5 minutes 6.16 seconds. Current RSS: ~1235M. Threads: 1. load average: 1.05 1.11 0.76 1/263 392
28017:54:24.
28117:54:24# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb. Expected to take 2 minutes 24.99 seconds.
28217:54:24Gitlab::BackgroundMigration::BackfillFindingIdInVulnerabilities
28317:56:03 #perform
28417:56:18 backfills finding_id column in the vulnerabilities table
28517:56:32 does not affect rows with finding_id populated
28617:56:32# [RSpecRunTime] RSpec elapsed time: 7 minutes 13.95 seconds. Current RSS: ~1251M. Threads: 1. load average: 1.04 1.07 0.80 1/264 393
28717:56:32.
28817:56:33I, [2024-11-07T17:56:33.526924 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
28917:56:53I, [2024-11-07T17:56:53.803566 #345] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
29017:56:55INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
29117:56:55INFO: analyzing "public.ci_pipeline_variables"
29217:56:55INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
29317:56:55I, [2024-11-07T17:56:55.462743 #345] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
29417:56:55I, [2024-11-07T17:56:55.463827 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
29517:56:55I, [2024-11-07T17:56:55.464603 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
29617:56:57INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
29717:56:57INFO: analyzing "public.ci_pipeline_variables"
29817:56:57INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
29917:57:01INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
30017:57:01INFO: analyzing "public.ci_job_artifacts"
30117:57:01INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
30217:57:01I, [2024-11-07T17:57:01.892771 #345] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
30317:57:01I, [2024-11-07T17:57:01.894024 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
30417:57:01I, [2024-11-07T17:57:01.894895 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
30517:57:05INFO: analyzing "public.p_ci_stages" inheritance tree
30617:57:05INFO: analyzing "public.ci_stages"
30717:57:05INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
30817:57:05I, [2024-11-07T17:57:05.452467 #345] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
30917:57:05I, [2024-11-07T17:57:05.453614 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
31017:57:05I, [2024-11-07T17:57:05.454438 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
31117:57:06I, [2024-11-07T17:57:06.784098 #345] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
31217:57:13I, [2024-11-07T17:57:13.398956 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
31317:57:27I, [2024-11-07T17:57:27.358942 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
31417:57:27I, [2024-11-07T17:57:27.360274 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
31517:57:27I, [2024-11-07T17:57:27.361106 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
31617:57:39I, [2024-11-07T17:57:39.531361 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
31717:57:46I, [2024-11-07T17:57:46.448787 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
31817:57:54I, [2024-11-07T17:57:54.398582 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
31917:57:56I, [2024-11-07T17:57:56.957235 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
32017:58:00INFO: analyzing "public.p_ci_pipelines" inheritance tree
32117:58:00INFO: analyzing "public.ci_pipelines"
32217:58:00INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
32317:58:00I, [2024-11-07T17:58:00.824953 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
32417:58:00I, [2024-11-07T17:58:00.826051 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
32517:58:00I, [2024-11-07T17:58:00.826861 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
32617:58:06I, [2024-11-07T17:58:06.199872 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
32717:58:16I, [2024-11-07T17:58:16.230655 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
32817:58:16I, [2024-11-07T17:58:16.231844 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
32917:58:16I, [2024-11-07T17:58:16.232689 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
33017:58:16I, [2024-11-07T17:58:16.236282 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
33117:58:16I, [2024-11-07T17:58:16.237473 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
33217:58:16I, [2024-11-07T17:58:16.238315 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
33317:58:16I, [2024-11-07T17:58:16.241711 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
33417:58:16I, [2024-11-07T17:58:16.242792 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
33517:58:16I, [2024-11-07T17:58:16.243592 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
33617:58:16I, [2024-11-07T17:58:16.247460 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
33717:58:16I, [2024-11-07T17:58:16.248617 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
33817:58:16I, [2024-11-07T17:58:16.249500 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
33917:58:17I, [2024-11-07T17:58:17.197974 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
34017:58:17I, [2024-11-07T17:58:17.199108 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
34117:58:17I, [2024-11-07T17:58:17.199906 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
34217:58:17I, [2024-11-07T17:58:17.203655 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
34317:58:17I, [2024-11-07T17:58:17.204768 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
34417:58:17I, [2024-11-07T17:58:17.205596 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
34517:58:17I, [2024-11-07T17:58:17.208771 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
34617:58:17I, [2024-11-07T17:58:17.209808 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
34717:58:17I, [2024-11-07T17:58:17.210619 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
34817:58:17I, [2024-11-07T17:58:17.213696 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
34917:58:17I, [2024-11-07T17:58:17.214755 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
35017:58:17I, [2024-11-07T17:58:17.215499 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
35117:58:33# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb. It took 4 minutes 8.89 seconds. Expected to take 2 minutes 24.99 seconds.
35217:58:33# [RSpecRunTime] RSpec elapsed time: 9 minutes 15.1 seconds. Current RSS: ~1247M. Threads: 1. load average: 0.94 1.02 0.82 1/268 394
35317:58:33.
35417:58:33# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_namespace_id_of_vulnerability_reads_spec.rb. Expected to take 2 minutes 4.75 seconds.
35517:58:33Gitlab::BackgroundMigration::BackfillNamespaceIdOfVulnerabilityReads
35618:00:34 sets the namespace_id of existing record
35718:00:36I, [2024-11-07T18:00:36.053217 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
35818:00:57I, [2024-11-07T18:00:57.823532 #345] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
35918:00:59INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
36018:00:59INFO: analyzing "public.ci_pipeline_variables"
36118:00:59INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
36218:00:59I, [2024-11-07T18:00:59.802793 #345] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
36318:00:59I, [2024-11-07T18:00:59.804042 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
36418:00:59I, [2024-11-07T18:00:59.804827 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
36518:01:01INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
36618:01:01INFO: analyzing "public.ci_pipeline_variables"
36718:01:01INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
36818:01:06INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
36918:01:06INFO: analyzing "public.ci_job_artifacts"
37018:01:06INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
37118:01:06I, [2024-11-07T18:01:06.428810 #345] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
37218:01:06I, [2024-11-07T18:01:06.430139 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
37318:01:06I, [2024-11-07T18:01:06.431066 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
37418:01:10INFO: analyzing "public.p_ci_stages" inheritance tree
37518:01:10INFO: analyzing "public.ci_stages"
37618:01:10INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
37718:01:10I, [2024-11-07T18:01:10.037822 #345] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
37818:01:10I, [2024-11-07T18:01:10.039011 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
37918:01:10I, [2024-11-07T18:01:10.039851 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
38018:01:11I, [2024-11-07T18:01:11.440893 #345] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
38118:01:18I, [2024-11-07T18:01:18.230241 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
38218:01:31I, [2024-11-07T18:01:31.899655 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
38318:01:31I, [2024-11-07T18:01:31.900849 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
38418:01:31I, [2024-11-07T18:01:31.901681 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
38518:01:44I, [2024-11-07T18:01:44.128117 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
38618:01:51I, [2024-11-07T18:01:51.110650 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
38718:01:59I, [2024-11-07T18:01:59.004110 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
38818:02:01I, [2024-11-07T18:02:01.709471 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
38918:02:05INFO: analyzing "public.p_ci_pipelines" inheritance tree
39018:02:05INFO: analyzing "public.ci_pipelines"
39118:02:05INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
39218:02:05I, [2024-11-07T18:02:05.479972 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
39318:02:05I, [2024-11-07T18:02:05.481132 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
39418:02:05I, [2024-11-07T18:02:05.481954 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
39518:02:11I, [2024-11-07T18:02:11.008981 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
39618:02:21I, [2024-11-07T18:02:21.061194 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
39718:02:21I, [2024-11-07T18:02:21.062277 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
39818:02:21I, [2024-11-07T18:02:21.063031 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
39918:02:21I, [2024-11-07T18:02:21.066257 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
40018:02:21I, [2024-11-07T18:02:21.067317 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
40118:02:21I, [2024-11-07T18:02:21.068062 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
40218:02:21I, [2024-11-07T18:02:21.071106 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
40318:02:21I, [2024-11-07T18:02:21.072117 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
40418:02:21I, [2024-11-07T18:02:21.072890 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
40518:02:21I, [2024-11-07T18:02:21.076069 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
40618:02:21I, [2024-11-07T18:02:21.077110 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
40718:02:21I, [2024-11-07T18:02:21.077932 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
40818:02:22I, [2024-11-07T18:02:22.020281 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
40918:02:22I, [2024-11-07T18:02:22.021452 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
41018:02:22I, [2024-11-07T18:02:22.022310 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
41118:02:22I, [2024-11-07T18:02:22.025531 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
41218:02:22I, [2024-11-07T18:02:22.026584 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
41318:02:22I, [2024-11-07T18:02:22.027342 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
41418:02:22I, [2024-11-07T18:02:22.030479 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
41518:02:22I, [2024-11-07T18:02:22.031533 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
41618:02:22I, [2024-11-07T18:02:22.032335 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
41718:02:22I, [2024-11-07T18:02:22.035438 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
41818:02:22I, [2024-11-07T18:02:22.036477 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
41918:02:22I, [2024-11-07T18:02:22.037282 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
42018:02:38# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_namespace_id_of_vulnerability_reads_spec.rb. It took 4 minutes 4.7 seconds. Expected to take 2 minutes 4.75 seconds.
42118:02:38# [RSpecRunTime] RSpec elapsed time: 13 minutes 19.84 seconds. Current RSS: ~1256M. Threads: 1. load average: 1.16 1.08 0.90 1/268 395
42218:02:38.
42318:02:38# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_default_organization_users_spec.rb. Expected to take 1 minute 49.57 seconds.
42418:02:38Gitlab::BackgroundMigration::BackfillDefaultOrganizationUsers
42518:03:53 #perform
42618:03:53 with no entries for a regular user in organization_users
42718:04:03 adds regular users correctly with the default organization to organization_users
42818:04:04# [RSpecRunTime] RSpec elapsed time: 14 minutes 45.4 seconds. Current RSS: ~1287M. Threads: 1. load average: 1.00 1.07 0.92 1/266 396
42918:04:04.
43018:04:04 when user already exists in organization_users as an admin user
43118:04:14 updates the organization_users entry to a regular user
43218:04:14# [RSpecRunTime] RSpec elapsed time: 14 minutes 55.86 seconds. Current RSS: ~1268M. Threads: 1. load average: 1.00 1.06 0.92 1/267 397
43318:04:14.
43418:04:15INFO: analyzing "public.p_ci_stages" inheritance tree
43518:04:15INFO: analyzing "public.ci_stages"
43618:04:15INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
43718:04:15I, [2024-11-07T18:04:15.878579 #345] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
43818:04:15I, [2024-11-07T18:04:15.879883 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
43918:04:15I, [2024-11-07T18:04:15.880800 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
44018:04:17I, [2024-11-07T18:04:17.215574 #345] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
44118:04:23I, [2024-11-07T18:04:23.970701 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
44218:04:38I, [2024-11-07T18:04:38.546833 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
44318:04:38I, [2024-11-07T18:04:38.547965 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
44418:04:38I, [2024-11-07T18:04:38.548721 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
44518:04:51I, [2024-11-07T18:04:51.334620 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
44618:04:58I, [2024-11-07T18:04:58.954182 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
44718:05:07I, [2024-11-07T18:05:07.551270 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
44818:05:10I, [2024-11-07T18:05:10.242273 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
44918:05:14INFO: analyzing "public.p_ci_pipelines" inheritance tree
45018:05:14INFO: analyzing "public.ci_pipelines"
45118:05:14INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
45218:05:14I, [2024-11-07T18:05:14.100414 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
45318:05:14I, [2024-11-07T18:05:14.101632 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
45418:05:14I, [2024-11-07T18:05:14.102440 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
45518:05:19I, [2024-11-07T18:05:19.958672 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
45618:05:30I, [2024-11-07T18:05:30.743151 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
45718:05:30I, [2024-11-07T18:05:30.744304 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
45818:05:30I, [2024-11-07T18:05:30.745104 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
45918:05:30I, [2024-11-07T18:05:30.748506 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
46018:05:30I, [2024-11-07T18:05:30.749708 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
46118:05:30I, [2024-11-07T18:05:30.750599 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
46218:05:30I, [2024-11-07T18:05:30.753953 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
46318:05:30I, [2024-11-07T18:05:30.755395 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
46418:05:30I, [2024-11-07T18:05:30.756162 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
46518:05:30I, [2024-11-07T18:05:30.759485 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
46618:05:30I, [2024-11-07T18:05:30.760502 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
46718:05:30I, [2024-11-07T18:05:30.761293 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
46818:05:31I, [2024-11-07T18:05:31.802944 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
46918:05:31I, [2024-11-07T18:05:31.804133 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
47018:05:31I, [2024-11-07T18:05:31.805016 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
47118:05:31I, [2024-11-07T18:05:31.809385 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
47218:05:31I, [2024-11-07T18:05:31.810542 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
47318:05:31I, [2024-11-07T18:05:31.811419 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
47418:05:31I, [2024-11-07T18:05:31.815006 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
47518:05:31I, [2024-11-07T18:05:31.816129 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
47618:05:31I, [2024-11-07T18:05:31.816984 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
47718:05:31I, [2024-11-07T18:05:31.820511 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
47818:05:31I, [2024-11-07T18:05:31.821656 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
47918:05:31I, [2024-11-07T18:05:31.822526 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
48018:05:48# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_default_organization_users_spec.rb. It took 3 minutes 10.35 seconds. Expected to take 1 minute 49.57 seconds.
48118:05:48# [RSpecRunTime] RSpec elapsed time: 16 minutes 30.23 seconds. Current RSS: ~1237M. Threads: 1. load average: 1.20 1.09 0.94 1/267 398
48218:05:48.
48318:05:48# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_issue_search_data_namespace_id_spec.rb. Expected to take 1 minute 44.59 seconds.
48418:05:48Gitlab::BackgroundMigration::BackfillIssueSearchDataNamespaceId
48518:07:23WARNING: Active Record does not support composite primary key.
48618:07:23issue_search_data has composite primary key. Composite primary key is ignored.
48718:07:23WARNING: Active Record does not support composite primary key.
48818:07:23issue_search_data has composite primary key. Composite primary key is ignored.
48918:07:27 backfills namespace_id for the specified records
49018:07:30I, [2024-11-07T18:07:30.652793 #345] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
49118:07:32INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
49218:07:32INFO: analyzing "public.ci_pipeline_variables"
49318:07:32INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
49418:07:32I, [2024-11-07T18:07:32.410888 #345] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
49518:07:32I, [2024-11-07T18:07:32.412070 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
49618:07:32I, [2024-11-07T18:07:32.412856 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
49718:07:34INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
49818:07:34INFO: analyzing "public.ci_pipeline_variables"
49918:07:34INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
50018:07:39INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
50118:07:39INFO: analyzing "public.ci_job_artifacts"
50218:07:39INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
50318:07:39I, [2024-11-07T18:07:39.058610 #345] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
50418:07:39I, [2024-11-07T18:07:39.059831 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
50518:07:39I, [2024-11-07T18:07:39.060720 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
50618:07:42INFO: analyzing "public.p_ci_stages" inheritance tree
50718:07:42INFO: analyzing "public.ci_stages"
50818:07:42INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
50918:07:42I, [2024-11-07T18:07:42.677276 #345] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
51018:07:42I, [2024-11-07T18:07:42.678651 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
51118:07:42I, [2024-11-07T18:07:42.679521 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
51218:07:44I, [2024-11-07T18:07:44.042854 #345] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
51318:07:50I, [2024-11-07T18:07:50.757476 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
51418:08:05I, [2024-11-07T18:08:05.773082 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
51518:08:05I, [2024-11-07T18:08:05.774293 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
51618:08:05I, [2024-11-07T18:08:05.775020 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
51718:08:18I, [2024-11-07T18:08:18.758640 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
51818:08:26I, [2024-11-07T18:08:26.318719 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
51918:08:34I, [2024-11-07T18:08:34.796225 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
52018:08:37I, [2024-11-07T18:08:37.491440 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
52118:08:41INFO: analyzing "public.p_ci_pipelines" inheritance tree
52218:08:41INFO: analyzing "public.ci_pipelines"
52318:08:41INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
52418:08:41I, [2024-11-07T18:08:41.385673 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
52518:08:41I, [2024-11-07T18:08:41.386953 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
52618:08:41I, [2024-11-07T18:08:41.387813 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
52718:08:47I, [2024-11-07T18:08:47.387021 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
52818:08:58I, [2024-11-07T18:08:58.451228 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
52918:08:58I, [2024-11-07T18:08:58.452356 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
53018:08:58I, [2024-11-07T18:08:58.453210 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
53118:08:58I, [2024-11-07T18:08:58.456860 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
53218:08:58I, [2024-11-07T18:08:58.458008 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
53318:08:58I, [2024-11-07T18:08:58.458829 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
53418:08:58I, [2024-11-07T18:08:58.462620 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
53518:08:58I, [2024-11-07T18:08:58.463866 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
53618:08:58I, [2024-11-07T18:08:58.464838 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
53718:08:58I, [2024-11-07T18:08:58.468385 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
53818:08:58I, [2024-11-07T18:08:58.469511 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
53918:08:58I, [2024-11-07T18:08:58.470324 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
54018:08:59I, [2024-11-07T18:08:59.608992 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
54118:08:59I, [2024-11-07T18:08:59.610402 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
54218:08:59I, [2024-11-07T18:08:59.611322 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
54318:08:59I, [2024-11-07T18:08:59.615615 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
54418:08:59I, [2024-11-07T18:08:59.617753 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
54518:08:59I, [2024-11-07T18:08:59.618908 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
54618:08:59I, [2024-11-07T18:08:59.623401 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
54718:08:59I, [2024-11-07T18:08:59.624725 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
54818:08:59I, [2024-11-07T18:08:59.625634 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
54918:08:59I, [2024-11-07T18:08:59.630516 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
55018:08:59I, [2024-11-07T18:08:59.631906 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
55118:08:59I, [2024-11-07T18:08:59.632882 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
55218:09:18# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_issue_search_data_namespace_id_spec.rb. It took 3 minutes 29.17 seconds. Expected to take 1 minute 44.59 seconds.
55318:09:18# [RSpecRunTime] RSpec elapsed time: 19 minutes 59.44 seconds. Current RSS: ~1250M. Threads: 1. load average: 1.01 1.07 0.98 1/267 399
55418:09:18.
55518:09:18# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_work_item_parent_links_namespace_id_spec.rb. Expected to take 1 minute 31.85 seconds.
55618:09:18Gitlab::BackgroundMigration::BackfillWorkItemParentLinksNamespaceId
55718:10:33 constructs a valid query
55818:10:41 performs without error
55918:10:43I, [2024-11-07T18:10:43.061336 #345] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
56018:10:57I, [2024-11-07T18:10:57.001918 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
56118:10:57I, [2024-11-07T18:10:57.003737 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
56218:10:57I, [2024-11-07T18:10:57.004548 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
56318:11:09I, [2024-11-07T18:11:09.459373 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
56418:11:16I, [2024-11-07T18:11:16.624487 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
56518:11:24I, [2024-11-07T18:11:24.785795 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
56618:11:27I, [2024-11-07T18:11:27.439092 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
56718:11:31INFO: analyzing "public.p_ci_pipelines" inheritance tree
56818:11:31INFO: analyzing "public.ci_pipelines"
56918:11:31INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
57018:11:31I, [2024-11-07T18:11:31.227729 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
57118:11:31I, [2024-11-07T18:11:31.228823 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
57218:11:31I, [2024-11-07T18:11:31.229572 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
57318:11:36I, [2024-11-07T18:11:36.764948 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
57418:11:47I, [2024-11-07T18:11:47.234710 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
57518:11:47I, [2024-11-07T18:11:47.235910 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
57618:11:47I, [2024-11-07T18:11:47.236746 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
57718:11:47I, [2024-11-07T18:11:47.240072 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
57818:11:47I, [2024-11-07T18:11:47.241163 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
57918:11:47I, [2024-11-07T18:11:47.241975 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
58018:11:47I, [2024-11-07T18:11:47.245231 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
58118:11:47I, [2024-11-07T18:11:47.246641 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
58218:11:47I, [2024-11-07T18:11:47.247426 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
58318:11:47I, [2024-11-07T18:11:47.250756 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
58418:11:47I, [2024-11-07T18:11:47.252007 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
58518:11:47I, [2024-11-07T18:11:47.252807 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
58618:11:48I, [2024-11-07T18:11:48.235804 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
58718:11:48I, [2024-11-07T18:11:48.236904 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
58818:11:48I, [2024-11-07T18:11:48.237660 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
58918:11:48I, [2024-11-07T18:11:48.240656 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
59018:11:48I, [2024-11-07T18:11:48.241705 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
59118:11:48I, [2024-11-07T18:11:48.242522 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
59218:11:48I, [2024-11-07T18:11:48.245929 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
59318:11:48I, [2024-11-07T18:11:48.247049 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
59418:11:48I, [2024-11-07T18:11:48.247840 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
59518:11:48I, [2024-11-07T18:11:48.251120 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
59618:11:48I, [2024-11-07T18:11:48.252224 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
59718:11:48I, [2024-11-07T18:11:48.252958 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
59818:12:04# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_work_item_parent_links_namespace_id_spec.rb. It took 2 minutes 46.71 seconds. Expected to take 1 minute 31.85 seconds.
59918:12:04# [RSpecRunTime] RSpec elapsed time: 22 minutes 46.19 seconds. Current RSS: ~1255M. Threads: 1. load average: 1.08 1.09 1.00 1/267 400
60018:12:04.
60118:12:04# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_dora_daily_metrics_project_id_spec.rb. Expected to take 1 minute 20.39 seconds.
60218:12:04Gitlab::BackgroundMigration::BackfillDoraDailyMetricsProjectId
60318:13:02 performs without error
60418:13:10 constructs a valid query
60518:13:11I, [2024-11-07T18:13:11.628380 #345] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
60618:13:11I, [2024-11-07T18:13:11.629572 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
60718:13:11I, [2024-11-07T18:13:11.630346 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
60818:13:23I, [2024-11-07T18:13:23.684543 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
60918:13:30I, [2024-11-07T18:13:30.916329 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
61018:13:39I, [2024-11-07T18:13:39.219160 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
61118:13:41I, [2024-11-07T18:13:41.790709 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
61218:13:45INFO: analyzing "public.p_ci_pipelines" inheritance tree
61318:13:45INFO: analyzing "public.ci_pipelines"
61418:13:45INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
61518:13:45I, [2024-11-07T18:13:45.741919 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
61618:13:45I, [2024-11-07T18:13:45.743137 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
61718:13:45I, [2024-11-07T18:13:45.743963 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
61818:13:51I, [2024-11-07T18:13:51.641374 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
61918:14:02I, [2024-11-07T18:14:02.612266 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
62018:14:02I, [2024-11-07T18:14:02.613399 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
62118:14:02I, [2024-11-07T18:14:02.614276 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
62218:14:02I, [2024-11-07T18:14:02.617733 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
62318:14:02I, [2024-11-07T18:14:02.618897 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
62418:14:02I, [2024-11-07T18:14:02.619786 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
62518:14:02I, [2024-11-07T18:14:02.623212 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
62618:14:02I, [2024-11-07T18:14:02.624323 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
62718:14:02I, [2024-11-07T18:14:02.625086 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
62818:14:02I, [2024-11-07T18:14:02.628364 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
62918:14:02I, [2024-11-07T18:14:02.629404 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
63018:14:02I, [2024-11-07T18:14:02.630253 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
63118:14:03I, [2024-11-07T18:14:03.700819 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
63218:14:03I, [2024-11-07T18:14:03.702041 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
63318:14:03I, [2024-11-07T18:14:03.702937 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
63418:14:03I, [2024-11-07T18:14:03.706945 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
63518:14:03I, [2024-11-07T18:14:03.708033 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
63618:14:03I, [2024-11-07T18:14:03.708890 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
63718:14:03I, [2024-11-07T18:14:03.712400 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
63818:14:03I, [2024-11-07T18:14:03.713505 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
63918:14:03I, [2024-11-07T18:14:03.714330 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
64018:14:03I, [2024-11-07T18:14:03.717877 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
64118:14:03I, [2024-11-07T18:14:03.718988 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
64218:14:03I, [2024-11-07T18:14:03.719835 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
64318:14:20# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_dora_daily_metrics_project_id_spec.rb. It took 2 minutes 15.22 seconds. Expected to take 1 minute 20.39 seconds.
64418:14:20# [RSpecRunTime] RSpec elapsed time: 25 minutes 1.45 seconds. Current RSS: ~1256M. Threads: 1. load average: 0.98 1.05 1.00 1/268 401
64518:14:20.
64618:14:20# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_dast_site_profile_secret_variables_project_id_spec.rb. Expected to take 1 minute 16.89 seconds.
64718:14:20Gitlab::BackgroundMigration::BackfillDastSiteProfileSecretVariablesProjectId
64818:15:20 constructs a valid query
64918:15:28 performs without error
65018:15:40I, [2024-11-07T18:15:40.629779 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
65118:15:47I, [2024-11-07T18:15:47.845858 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
65218:15:55I, [2024-11-07T18:15:55.815243 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
65318:15:58I, [2024-11-07T18:15:58.356011 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
65418:16:02INFO: analyzing "public.p_ci_pipelines" inheritance tree
65518:16:02INFO: analyzing "public.ci_pipelines"
65618:16:02INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
65718:16:02I, [2024-11-07T18:16:02.493930 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
65818:16:02I, [2024-11-07T18:16:02.495127 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
65918:16:02I, [2024-11-07T18:16:02.496195 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
66018:16:08I, [2024-11-07T18:16:08.773208 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
66118:16:19I, [2024-11-07T18:16:19.092480 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
66218:16:19I, [2024-11-07T18:16:19.093544 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
66318:16:19I, [2024-11-07T18:16:19.094316 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
66418:16:19I, [2024-11-07T18:16:19.097719 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
66518:16:19I, [2024-11-07T18:16:19.098794 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
66618:16:19I, [2024-11-07T18:16:19.099558 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
66718:16:19I, [2024-11-07T18:16:19.102867 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
66818:16:19I, [2024-11-07T18:16:19.103953 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
66918:16:19I, [2024-11-07T18:16:19.104743 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
67018:16:19I, [2024-11-07T18:16:19.107787 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
67118:16:19I, [2024-11-07T18:16:19.108831 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
67218:16:19I, [2024-11-07T18:16:19.109595 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
67318:16:20I, [2024-11-07T18:16:20.106860 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
67418:16:20I, [2024-11-07T18:16:20.108019 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
67518:16:20I, [2024-11-07T18:16:20.108881 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
67618:16:20I, [2024-11-07T18:16:20.112402 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
67718:16:20I, [2024-11-07T18:16:20.113450 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
67818:16:20I, [2024-11-07T18:16:20.114248 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
67918:16:20I, [2024-11-07T18:16:20.117636 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
68018:16:20I, [2024-11-07T18:16:20.118809 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
68118:16:20I, [2024-11-07T18:16:20.119665 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
68218:16:20I, [2024-11-07T18:16:20.123610 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
68318:16:20I, [2024-11-07T18:16:20.124691 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
68418:16:20I, [2024-11-07T18:16:20.125510 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
68518:16:36# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_dast_site_profile_secret_variables_project_id_spec.rb. It took 2 minutes 16.02 seconds. Expected to take 1 minute 16.89 seconds.
68618:16:36# [RSpecRunTime] RSpec elapsed time: 27 minutes 17.51 seconds. Current RSS: ~1247M. Threads: 1. load average: 1.01 1.07 1.01 1/268 402
68718:16:36.
68818:16:36# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_epic_user_mentions_group_id_spec.rb. Expected to take 1 minute 15.69 seconds.
68918:16:36Gitlab::BackgroundMigration::BackfillEpicUserMentionsGroupId
69018:17:31 constructs a valid query
69118:17:39 performs without error
69218:17:51I, [2024-11-07T18:17:51.203604 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
69318:17:58I, [2024-11-07T18:17:58.439976 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
69418:18:06I, [2024-11-07T18:18:06.768375 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
69518:18:09I, [2024-11-07T18:18:09.508776 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
69618:18:13INFO: analyzing "public.p_ci_pipelines" inheritance tree
69718:18:13INFO: analyzing "public.ci_pipelines"
69818:18:13INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
69918:18:13I, [2024-11-07T18:18:13.549429 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
70018:18:13I, [2024-11-07T18:18:13.550826 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
70118:18:13I, [2024-11-07T18:18:13.551813 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
70218:18:19I, [2024-11-07T18:18:19.319323 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
70318:18:29I, [2024-11-07T18:18:29.922327 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
70418:18:29I, [2024-11-07T18:18:29.924048 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
70518:18:29I, [2024-11-07T18:18:29.924935 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
70618:18:29I, [2024-11-07T18:18:29.928652 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
70718:18:29I, [2024-11-07T18:18:29.929829 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
70818:18:29I, [2024-11-07T18:18:29.930649 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
70918:18:29I, [2024-11-07T18:18:29.934200 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
71018:18:29I, [2024-11-07T18:18:29.935321 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
71118:18:29I, [2024-11-07T18:18:29.936193 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
71218:18:29I, [2024-11-07T18:18:29.939832 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
71318:18:29I, [2024-11-07T18:18:29.941079 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
71418:18:29I, [2024-11-07T18:18:29.942304 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
71518:18:31I, [2024-11-07T18:18:31.003235 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
71618:18:31I, [2024-11-07T18:18:31.004545 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
71718:18:31I, [2024-11-07T18:18:31.005526 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
71818:18:31I, [2024-11-07T18:18:31.008832 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
71918:18:31I, [2024-11-07T18:18:31.009880 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
72018:18:31I, [2024-11-07T18:18:31.010661 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
72118:18:31I, [2024-11-07T18:18:31.013768 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
72218:18:31I, [2024-11-07T18:18:31.014887 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
72318:18:31I, [2024-11-07T18:18:31.015652 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
72418:18:31I, [2024-11-07T18:18:31.018767 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
72518:18:31I, [2024-11-07T18:18:31.020013 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
72618:18:31I, [2024-11-07T18:18:31.020739 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
72718:18:48# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_epic_user_mentions_group_id_spec.rb. It took 2 minutes 12.13 seconds. Expected to take 1 minute 15.69 seconds.
72818:18:48# [RSpecRunTime] RSpec elapsed time: 29 minutes 29.69 seconds. Current RSS: ~1246M. Threads: 1. load average: 1.11 1.11 1.03 1/269 403
72918:18:48.
73018:18:48# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_dast_profiles_tags_project_id_spec.rb. Expected to take 1 minute 10.81 seconds.
73118:18:48Gitlab::BackgroundMigration::BackfillDastProfilesTagsProjectId
73218:19:54 performs without error
73318:20:04 constructs a valid query
73418:20:19I, [2024-11-07T18:20:18.998725 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
73518:20:27I, [2024-11-07T18:20:27.466225 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
73618:20:36I, [2024-11-07T18:20:36.739834 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
73718:20:39I, [2024-11-07T18:20:39.805939 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
73818:20:44INFO: analyzing "public.p_ci_pipelines" inheritance tree
73918:20:44INFO: analyzing "public.ci_pipelines"
74018:20:44INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
74118:20:44I, [2024-11-07T18:20:44.362860 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
74218:20:44I, [2024-11-07T18:20:44.364113 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
74318:20:44I, [2024-11-07T18:20:44.364972 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
74418:20:51I, [2024-11-07T18:20:51.399737 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
74518:21:03I, [2024-11-07T18:21:03.938526 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
74618:21:03I, [2024-11-07T18:21:03.940513 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
74718:21:03I, [2024-11-07T18:21:03.941595 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
74818:21:03I, [2024-11-07T18:21:03.945645 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
74918:21:03I, [2024-11-07T18:21:03.946805 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
75018:21:03I, [2024-11-07T18:21:03.947705 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
75118:21:03I, [2024-11-07T18:21:03.951493 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
75218:21:03I, [2024-11-07T18:21:03.952687 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
75318:21:03I, [2024-11-07T18:21:03.953560 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
75418:21:03I, [2024-11-07T18:21:03.957295 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
75518:21:03I, [2024-11-07T18:21:03.958412 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
75618:21:03I, [2024-11-07T18:21:03.959287 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
75718:21:05I, [2024-11-07T18:21:05.097347 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
75818:21:05I, [2024-11-07T18:21:05.098601 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
75918:21:05I, [2024-11-07T18:21:05.099485 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
76018:21:05I, [2024-11-07T18:21:05.103356 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
76118:21:05I, [2024-11-07T18:21:05.104602 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
76218:21:05I, [2024-11-07T18:21:05.105464 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
76318:21:05I, [2024-11-07T18:21:05.109332 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
76418:21:05I, [2024-11-07T18:21:05.110541 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
76518:21:05I, [2024-11-07T18:21:05.111503 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
76618:21:05I, [2024-11-07T18:21:05.115334 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
76718:21:05I, [2024-11-07T18:21:05.116554 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
76818:21:05I, [2024-11-07T18:21:05.117461 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
76918:21:23# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_dast_profiles_tags_project_id_spec.rb. It took 2 minutes 34.85 seconds. Expected to take 1 minute 10.81 seconds.
77018:21:23# [RSpecRunTime] RSpec elapsed time: 32 minutes 4.59 seconds. Current RSS: ~1245M. Threads: 1. load average: 0.84 1.05 1.01 1/269 404
77118:21:23.
77218:21:23# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb. Expected to take 1 minute 8.01 seconds.
77318:21:23Gitlab::BackgroundMigration::BackfillCatalogResourceVersionSemVer
77418:22:26 updates the semver columns with the expected values
77518:22:37I, [2024-11-07T18:22:37.361341 #345] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
77618:22:45I, [2024-11-07T18:22:45.982526 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
77718:22:56I, [2024-11-07T18:22:56.047540 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
77818:22:59I, [2024-11-07T18:22:59.351820 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
77918:23:04INFO: analyzing "public.p_ci_pipelines" inheritance tree
78018:23:04INFO: analyzing "public.ci_pipelines"
78118:23:04INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
78218:23:04I, [2024-11-07T18:23:04.311709 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
78318:23:04I, [2024-11-07T18:23:04.312986 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
78418:23:04I, [2024-11-07T18:23:04.314205 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
78518:23:11I, [2024-11-07T18:23:11.116516 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
78618:23:23I, [2024-11-07T18:23:23.794043 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
78718:23:23I, [2024-11-07T18:23:23.795557 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
78818:23:23I, [2024-11-07T18:23:23.796502 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
78918:23:23I, [2024-11-07T18:23:23.801527 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
79018:23:23I, [2024-11-07T18:23:23.802799 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
79118:23:23I, [2024-11-07T18:23:23.803670 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
79218:23:23I, [2024-11-07T18:23:23.807578 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
79318:23:23I, [2024-11-07T18:23:23.808845 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
79418:23:23I, [2024-11-07T18:23:23.809778 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
79518:23:23I, [2024-11-07T18:23:23.814028 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
79618:23:23I, [2024-11-07T18:23:23.815304 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
79718:23:23I, [2024-11-07T18:23:23.816230 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
79818:23:25I, [2024-11-07T18:23:25.073188 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
79918:23:25I, [2024-11-07T18:23:25.074615 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
80018:23:25I, [2024-11-07T18:23:25.075527 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
80118:23:25I, [2024-11-07T18:23:25.079122 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
80218:23:25I, [2024-11-07T18:23:25.080813 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
80318:23:25I, [2024-11-07T18:23:25.081622 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
80418:23:25I, [2024-11-07T18:23:25.085116 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
80518:23:25I, [2024-11-07T18:23:25.086311 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
80618:23:25I, [2024-11-07T18:23:25.087139 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
80718:23:25I, [2024-11-07T18:23:25.090642 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
80818:23:25I, [2024-11-07T18:23:25.091808 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
80918:23:25I, [2024-11-07T18:23:25.092619 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
81018:23:43# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb. It took 2 minutes 20.47 seconds. Expected to take 1 minute 8.01 seconds.
81118:23:43# [RSpecRunTime] RSpec elapsed time: 34 minutes 25.1 seconds. Current RSS: ~1257M. Threads: 1. load average: 1.10 1.10 1.03 1/269 405
81218:23:43.
81318:23:43# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_vulnerability_finding_signatures_project_id_spec.rb. Expected to take 1 minute 0.52 second.
81418:23:43Gitlab::BackgroundMigration::BackfillVulnerabilityFindingSignaturesProjectId
81518:24:40 constructs a valid query
81618:24:48 performs without error
81718:24:48The application_settings (main) table has 1217 columns.
81818:24:48Recreating the database
81918:24:48Dropped database 'gitlabhq_test'
82018:24:49Dropped database 'gitlabhq_test_ci'
82118:24:49Created database 'gitlabhq_test'
82218:24:49Created database 'gitlabhq_test_ci'
82318:25:01main: == [advisory_lock_connection] object_id: 381314680, pg_backend_pid: 358
82418:25:01main: == [advisory_lock_connection] object_id: 381314680, pg_backend_pid: 358
82518:25:01ci: == [advisory_lock_connection] object_id: 381345700, pg_backend_pid: 360
82618:25:01ci: == [advisory_lock_connection] object_id: 381345700, pg_backend_pid: 360
82718:25:09Databases re-creation done in 21.153602630000023
82818:25:09# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_vulnerability_finding_signatures_project_id_spec.rb. It took 1 minute 25.73 seconds. Expected to take 1 minute 0.52 second.
82918:25:09# [RSpecRunTime] RSpec elapsed time: 35 minutes 50.88 seconds. Current RSS: ~1252M. Threads: 1. load average: 0.98 1.06 1.02 1/269 408
83018:25:09.
83118:25:09# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_ci_unit_test_failures_project_id_spec.rb. Expected to take 58.25 seconds.
83218:25:09Gitlab::BackgroundMigration::BackfillCiUnitTestFailuresProjectId
83318:25:53 performs without error
83418:25:58 constructs a valid query
83518:26:09I, [2024-11-07T18:26:09.806687 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
83618:26:09I, [2024-11-07T18:26:09.807830 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
83718:26:09I, [2024-11-07T18:26:09.808660 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
83818:26:09I, [2024-11-07T18:26:09.812197 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
83918:26:09I, [2024-11-07T18:26:09.813315 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
84018:26:09I, [2024-11-07T18:26:09.814084 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
84118:26:09I, [2024-11-07T18:26:09.817677 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
84218:26:09I, [2024-11-07T18:26:09.818962 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
84318:26:09I, [2024-11-07T18:26:09.819822 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
84418:26:09I, [2024-11-07T18:26:09.823853 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
84518:26:09I, [2024-11-07T18:26:09.825131 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
84618:26:09I, [2024-11-07T18:26:09.826015 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
84718:26:10I, [2024-11-07T18:26:10.885935 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
84818:26:10I, [2024-11-07T18:26:10.887209 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
84918:26:10I, [2024-11-07T18:26:10.888092 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
85018:26:10I, [2024-11-07T18:26:10.891794 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
85118:26:10I, [2024-11-07T18:26:10.892939 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
85218:26:10I, [2024-11-07T18:26:10.893765 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
85318:26:10I, [2024-11-07T18:26:10.897466 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
85418:26:10I, [2024-11-07T18:26:10.898609 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
85518:26:10I, [2024-11-07T18:26:10.899466 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
85618:26:10I, [2024-11-07T18:26:10.903209 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
85718:26:10I, [2024-11-07T18:26:10.904354 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
85818:26:10I, [2024-11-07T18:26:10.905284 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
85918:26:23I, [2024-11-07T18:26:23.613340 #345] INFO -- : Database: 'ci', Table: 'project_security_statistics': Lock Writes
86018:26:23I, [2024-11-07T18:26:23.781485 #345] INFO -- : Database: 'ci', Table: 'custom_fields': Lock Writes
86118:26:23I, [2024-11-07T18:26:23.819801 #345] INFO -- : Database: 'ci', Table: 'custom_field_select_options': Lock Writes
86218:26:23I, [2024-11-07T18:26:23.859593 #345] INFO -- : Database: 'ci', Table: 'work_item_type_custom_fields': Lock Writes
86318:26:35I, [2024-11-07T18:26:35.351553 #345] INFO -- : Database: 'ci', Table: 'catalog_resource_component_last_usages': Lock Writes
86418:26:35I, [2024-11-07T18:26:35.605136 #345] INFO -- : Database: 'ci', Table: 'pm_cve_enrichment': Lock Writes
86518:26:36I, [2024-11-07T18:26:36.076942 #345] INFO -- : Database: 'ci', Table: 'pipl_users': Lock Writes
86618:26:36I, [2024-11-07T18:26:36.226506 #345] INFO -- : Database: 'ci', Table: 'vulnerability_representation_information': Lock Writes
86718:26:36I, [2024-11-07T18:26:36.882255 #345] INFO -- : Database: 'ci', Table: 'abuse_report_labels': Lock Writes
86818:26:36I, [2024-11-07T18:26:36.941744 #345] INFO -- : Database: 'ci', Table: 'abuse_report_label_links': Lock Writes
86918:26:37I, [2024-11-07T18:26:37.304666 #345] INFO -- : Database: 'ci', Table: 'work_item_weights_sources': Lock Writes
87018:26:38I, [2024-11-07T18:26:38.071751 #345] INFO -- : Database: 'ci', Table: 'analytics_cycle_analytics_stage_aggregations': Lock Writes
87118:26:51# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_ci_unit_test_failures_project_id_spec.rb. It took 1 minute 41.93 seconds. Expected to take 58.25 seconds.
87218:26:51# [RSpecRunTime] RSpec elapsed time: 37 minutes 32.87 seconds. Current RSS: ~1253M. Threads: 1. load average: 1.00 1.04 1.01 1/269 409
87318:26:51.
87418:26:51# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb. Expected to take 50.26 seconds.
87518:26:51Gitlab::BackgroundMigration::CopyColumnUsingBackgroundMigrationJob
87618:26:57 is expected to be < Gitlab::BackgroundMigration::BatchedMigrationJob
87718:26:57 #perform
87818:27:02 tracks timings of queries
87918:27:02 primary keys
88018:27:07 copies all in range
88118:27:07# [RSpecRunTime] RSpec elapsed time: 37 minutes 48.57 seconds. Current RSS: ~1264M. Threads: 1. load average: 0.78 0.99 0.99 1/270 410
88218:27:07.
88318:27:07 foreign keys
88418:27:12 copies all in range
88518:27:12# [RSpecRunTime] RSpec elapsed time: 37 minutes 53.52 seconds. Current RSS: ~1264M. Threads: 1. load average: 0.72 0.97 0.99 1/270 411
88618:27:12.
88718:27:12 columns with NULLs
88818:27:17 copies all in range
88918:27:17# [RSpecRunTime] RSpec elapsed time: 37 minutes 58.44 seconds. Current RSS: ~1261M. Threads: 1. load average: 0.66 0.95 0.98 1/270 412
89018:27:17.
89118:27:17 when multiple columns are given
89218:27:22 copies all values in the range
89318:27:22 when the number of source and target columns does not match
89418:27:27 raises an error
89518:27:27# [RSpecRunTime] RSpec elapsed time: 38 minutes 8.64 seconds. Current RSS: ~1266M. Threads: 1. load average: 0.71 0.95 0.98 1/270 413
89618:27:27.
89718:27:27 pause interval between sub-batches
89818:27:32 sleeps for the specified time between sub-batches
89918:27:32 when pause_ms value is negative
90018:27:37 treats it as a 0
90118:27:37# [RSpecRunTime] RSpec elapsed time: 38 minutes 18.47 seconds. Current RSS: ~1262M. Threads: 1. load average: 0.68 0.94 0.98 2/270 414
90218:27:37.
90318:27:49# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb. It took 58.21 seconds. Expected to take 50.26 seconds.
90418:27:49# [RSpecRunTime] RSpec elapsed time: 38 minutes 31.13 seconds. Current RSS: ~1258M. Threads: 1. load average: 0.75 0.94 0.98 1/270 415
90518:27:49.
90618:27:49# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_work_item_hierarchy_for_epics_spec.rb. Expected to take 47.24 seconds.
90718:27:49Gitlab::BackgroundMigration::BackfillWorkItemHierarchyForEpics
90818:28:30 backfills data correctly
90918:28:34I, [2024-11-07T18:28:34.118797 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
91018:28:43I, [2024-11-07T18:28:43.274388 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
91118:28:46I, [2024-11-07T18:28:46.141038 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
91218:28:50INFO: analyzing "public.p_ci_pipelines" inheritance tree
91318:28:50INFO: analyzing "public.ci_pipelines"
91418:28:50INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
91518:28:50I, [2024-11-07T18:28:50.214641 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
91618:28:50I, [2024-11-07T18:28:50.215823 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
91718:28:50I, [2024-11-07T18:28:50.216656 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
91818:28:55I, [2024-11-07T18:28:55.942032 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
91918:29:07I, [2024-11-07T18:29:07.213430 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
92018:29:07I, [2024-11-07T18:29:07.215118 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
92118:29:07I, [2024-11-07T18:29:07.216136 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
92218:29:07I, [2024-11-07T18:29:07.220548 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
92318:29:07I, [2024-11-07T18:29:07.221766 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
92418:29:07I, [2024-11-07T18:29:07.222708 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
92518:29:07I, [2024-11-07T18:29:07.227022 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
92618:29:07I, [2024-11-07T18:29:07.228356 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
92718:29:07I, [2024-11-07T18:29:07.229340 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
92818:29:07I, [2024-11-07T18:29:07.233658 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
92918:29:07I, [2024-11-07T18:29:07.235073 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
93018:29:07I, [2024-11-07T18:29:07.236033 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
93118:29:08I, [2024-11-07T18:29:08.350357 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
93218:29:08I, [2024-11-07T18:29:08.351560 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
93318:29:08I, [2024-11-07T18:29:08.352356 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
93418:29:08I, [2024-11-07T18:29:08.355668 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
93518:29:08I, [2024-11-07T18:29:08.356753 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
93618:29:08I, [2024-11-07T18:29:08.357533 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
93718:29:08I, [2024-11-07T18:29:08.361202 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
93818:29:08I, [2024-11-07T18:29:08.362282 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
93918:29:08I, [2024-11-07T18:29:08.363033 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
94018:29:08I, [2024-11-07T18:29:08.366208 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
94118:29:08I, [2024-11-07T18:29:08.367286 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
94218:29:08I, [2024-11-07T18:29:08.368021 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
94318:29:25# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_work_item_hierarchy_for_epics_spec.rb. It took 1 minute 35.74 seconds. Expected to take 47.24 seconds.
94418:29:25# [RSpecRunTime] RSpec elapsed time: 40 minutes 6.92 seconds. Current RSS: ~1249M. Threads: 1. load average: 0.86 0.92 0.97 1/270 416
94518:29:25.
94618:29:25# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_epic_dates_to_work_item_dates_sources_spec.rb. Expected to take 45.15 seconds.
94718:29:25Gitlab::BackgroundMigration::BackfillEpicDatesToWorkItemDatesSources
94818:29:59 when backfilling all epics
94918:30:07 backfills data correctly
95018:30:07# [RSpecRunTime] RSpec elapsed time: 40 minutes 48.58 seconds. Current RSS: ~1272M. Threads: 1. load average: 0.99 0.95 0.98 1/270 417
95118:30:07.
95218:30:10I, [2024-11-07T18:30:10.402883 #345] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
95318:30:19I, [2024-11-07T18:30:19.284259 #345] INFO -- : Database: 'main', Table: 'p_ci_build_trace_metadata': Lock Writes
95418:30:22I, [2024-11-07T18:30:22.128614 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines_config': Lock Writes
95518:30:26INFO: analyzing "public.p_ci_pipelines" inheritance tree
95618:30:26INFO: analyzing "public.ci_pipelines"
95718:30:26INFO: "ci_pipelines": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
95818:30:26I, [2024-11-07T18:30:26.033250 #345] INFO -- : Database: 'main', Table: 'p_ci_pipelines': Lock Writes
95918:30:26I, [2024-11-07T18:30:26.034342 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
96018:30:26I, [2024-11-07T18:30:26.035091 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
96118:30:31I, [2024-11-07T18:30:31.671943 #345] INFO -- : Database: 'main', Table: 'ci_job_token_authorizations': Lock Writes
96218:30:42I, [2024-11-07T18:30:42.857477 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
96318:30:42I, [2024-11-07T18:30:42.858752 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
96418:30:42I, [2024-11-07T18:30:42.859619 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
96518:30:42I, [2024-11-07T18:30:42.863387 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
96618:30:42I, [2024-11-07T18:30:42.864519 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
96718:30:42I, [2024-11-07T18:30:42.865338 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
96818:30:42I, [2024-11-07T18:30:42.869311 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
96918:30:42I, [2024-11-07T18:30:42.870488 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
97018:30:42I, [2024-11-07T18:30:42.871310 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
97118:30:42I, [2024-11-07T18:30:42.874902 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
97218:30:42I, [2024-11-07T18:30:42.876004 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
97318:30:42I, [2024-11-07T18:30:42.876830 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
97418:30:43I, [2024-11-07T18:30:43.922986 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
97518:30:43I, [2024-11-07T18:30:43.924358 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
97618:30:43I, [2024-11-07T18:30:43.925262 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
97718:30:43I, [2024-11-07T18:30:43.928982 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
97818:30:43I, [2024-11-07T18:30:43.930092 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
97918:30:43I, [2024-11-07T18:30:43.930956 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
98018:30:43I, [2024-11-07T18:30:43.934576 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
98118:30:43I, [2024-11-07T18:30:43.935699 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
98218:30:43I, [2024-11-07T18:30:43.936522 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
98318:30:43I, [2024-11-07T18:30:43.940495 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
98418:30:43I, [2024-11-07T18:30:43.941618 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
98518:30:43I, [2024-11-07T18:30:43.942473 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
98618:31:01# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_epic_dates_to_work_item_dates_sources_spec.rb. It took 1 minute 35.76 seconds. Expected to take 45.15 seconds.
98718:31:01# [RSpecRunTime] RSpec elapsed time: 41 minutes 42.72 seconds. Current RSS: ~1254M. Threads: 1. load average: 1.00 0.96 0.99 1/270 418
98818:31:01.
98918:31:01# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/batching_strategies/loose_index_scan_batching_strategy_spec.rb. Expected to take 28.97 seconds.
99018:31:01Gitlab::BackgroundMigration::BatchingStrategies::LooseIndexScanBatchingStrategy#next_batch
99118:31:07 is expected to be < Gitlab::BackgroundMigration::BatchingStrategies::BaseStrategy
99218:31:07 when starting on the first batch
99318:31:12 returns the bounds of the next batch
99418:31:12# [RSpecRunTime] RSpec elapsed time: 41 minutes 53.79 seconds. Current RSS: ~1262M. Threads: 1. load average: 0.92 0.94 0.98 1/270 419
99518:31:12.
99618:31:12 when additional batches remain
99718:31:17 returns the bounds of the next batch
99818:31:17# [RSpecRunTime] RSpec elapsed time: 41 minutes 58.94 seconds. Current RSS: ~1260M. Threads: 1. load average: 1.01 0.96 0.99 1/270 420
99918:31:17.
100018:31:17 when on the final batch
100118:31:22 returns the bounds of the next batch
100218:31:22# [RSpecRunTime] RSpec elapsed time: 42 minutes 4.23 seconds. Current RSS: ~1253M. Threads: 1. load average: 0.93 0.94 0.98 1/270 421
100318:31:22.
100418:31:22 when no additional batches remain
100518:31:28 returns nil
100618:31:28# [RSpecRunTime] RSpec elapsed time: 42 minutes 9.68 seconds. Current RSS: ~1254M. Threads: 1. load average: 0.93 0.95 0.98 1/270 422
100718:31:28.
100818:31:39# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/batching_strategies/loose_index_scan_batching_strategy_spec.rb. It took 38.23 seconds. Expected to take 28.97 seconds.
100918:31:39# [RSpecRunTime] RSpec elapsed time: 42 minutes 20.99 seconds. Current RSS: ~1253M. Threads: 1. load average: 0.95 0.95 0.98 1/270 423
101018:31:39.
101118:31:39# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_packages_rpm_metadata_project_id_spec.rb. Expected to take 25.37 seconds.
101218:31:39Gitlab::BackgroundMigration::BackfillPackagesRpmMetadataProjectId
101318:31:56 constructs a valid query
101418:32:01 performs without error
101518:32:11I, [2024-11-07T18:32:11.326665 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
101618:32:11I, [2024-11-07T18:32:11.327995 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
101718:32:11I, [2024-11-07T18:32:11.328976 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
101818:32:11I, [2024-11-07T18:32:11.333098 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
101918:32:11I, [2024-11-07T18:32:11.334314 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
102018:32:11I, [2024-11-07T18:32:11.335206 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
102118:32:11I, [2024-11-07T18:32:11.339240 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
102218:32:11I, [2024-11-07T18:32:11.340477 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
102318:32:11I, [2024-11-07T18:32:11.341368 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
102418:32:11I, [2024-11-07T18:32:11.345289 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
102518:32:11I, [2024-11-07T18:32:11.346558 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
102618:32:11I, [2024-11-07T18:32:11.347432 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
102718:32:12I, [2024-11-07T18:32:12.382116 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
102818:32:12I, [2024-11-07T18:32:12.383736 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
102918:32:12I, [2024-11-07T18:32:12.384768 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
103018:32:12I, [2024-11-07T18:32:12.388649 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
103118:32:12I, [2024-11-07T18:32:12.389797 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
103218:32:12I, [2024-11-07T18:32:12.390653 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
103318:32:12I, [2024-11-07T18:32:12.394154 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
103418:32:12I, [2024-11-07T18:32:12.395284 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
103518:32:12I, [2024-11-07T18:32:12.396092 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
103618:32:12I, [2024-11-07T18:32:12.399633 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
103718:32:12I, [2024-11-07T18:32:12.400787 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
103818:32:12I, [2024-11-07T18:32:12.401622 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
103918:32:29# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_packages_rpm_metadata_project_id_spec.rb. It took 49.7 seconds. Expected to take 25.37 seconds.
104018:32:29# [RSpecRunTime] RSpec elapsed time: 43 minutes 10.74 seconds. Current RSS: ~1264M. Threads: 1. load average: 0.93 0.94 0.98 1/270 424
104118:32:29.
104218:32:29# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_alert_management_alert_metric_images_project_id_spec.rb. Expected to take 24.0 seconds.
104318:32:29Gitlab::BackgroundMigration::BackfillAlertManagementAlertMetricImagesProjectId
104418:32:46 performs without error
104518:32:51 constructs a valid query
104618:33:02I, [2024-11-07T18:33:02.331303 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
104718:33:02I, [2024-11-07T18:33:02.332456 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
104818:33:02I, [2024-11-07T18:33:02.333285 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
104918:33:02I, [2024-11-07T18:33:02.336527 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
105018:33:02I, [2024-11-07T18:33:02.337985 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
105118:33:02I, [2024-11-07T18:33:02.338742 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
105218:33:02I, [2024-11-07T18:33:02.341931 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
105318:33:02I, [2024-11-07T18:33:02.343019 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
105418:33:02I, [2024-11-07T18:33:02.343795 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
105518:33:02I, [2024-11-07T18:33:02.347067 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
105618:33:02I, [2024-11-07T18:33:02.348069 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
105718:33:02I, [2024-11-07T18:33:02.348845 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
105818:33:03I, [2024-11-07T18:33:03.379336 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
105918:33:03I, [2024-11-07T18:33:03.380513 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
106018:33:03I, [2024-11-07T18:33:03.381379 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
106118:33:03I, [2024-11-07T18:33:03.384854 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
106218:33:03I, [2024-11-07T18:33:03.385968 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
106318:33:03I, [2024-11-07T18:33:03.386769 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
106418:33:03I, [2024-11-07T18:33:03.390278 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
106518:33:03I, [2024-11-07T18:33:03.391396 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
106618:33:03I, [2024-11-07T18:33:03.392237 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
106718:33:03I, [2024-11-07T18:33:03.395879 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
106818:33:03I, [2024-11-07T18:33:03.396976 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
106918:33:03I, [2024-11-07T18:33:03.397803 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
107018:33:19# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_alert_management_alert_metric_images_project_id_spec.rb. It took 49.73 seconds. Expected to take 24.0 seconds.
107118:33:19# [RSpecRunTime] RSpec elapsed time: 44 minutes 0.51 second. Current RSS: ~1261M. Threads: 1. load average: 0.97 0.95 0.99 1/269 425
107218:33:19.
107318:33:19# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_incident_management_pending_alert_escalations_project_id_spec.rb. Expected to take 22.89 seconds.
107418:33:19Gitlab::BackgroundMigration::BackfillIncidentManagementPendingAlertEscalationsProjectId
107518:33:34 performs without error
107618:33:38 constructs a valid query
107718:33:48I, [2024-11-07T18:33:48.724531 #345] INFO -- : Database: 'main', Table: 'ci_runners_e59bb2812d': Lock Writes
107818:33:48I, [2024-11-07T18:33:48.725769 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
107918:33:48I, [2024-11-07T18:33:48.726684 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
108018:33:48I, [2024-11-07T18:33:48.730420 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runners_e59bb2812d': Lock Writes
108118:33:48I, [2024-11-07T18:33:48.731599 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
108218:33:48I, [2024-11-07T18:33:48.732504 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
108318:33:48I, [2024-11-07T18:33:48.736367 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runners_e59bb2812d': Lock Writes
108418:33:48I, [2024-11-07T18:33:48.737562 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
108518:33:48I, [2024-11-07T18:33:48.738434 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
108618:33:48I, [2024-11-07T18:33:48.742055 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runners_e59bb2812d': Lock Writes
108718:33:48I, [2024-11-07T18:33:48.743273 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
108818:33:48I, [2024-11-07T18:33:48.744082 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
108918:33:49I, [2024-11-07T18:33:49.758914 #345] INFO -- : Database: 'main', Table: 'instance_type_ci_runner_machines_687967fa8a': Lock Writes
109018:33:49I, [2024-11-07T18:33:49.760101 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
109118:33:49I, [2024-11-07T18:33:49.760938 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
109218:33:49I, [2024-11-07T18:33:49.764637 #345] INFO -- : Database: 'main', Table: 'group_type_ci_runner_machines_687967fa8a': Lock Writes
109318:33:49I, [2024-11-07T18:33:49.765801 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
109418:33:49I, [2024-11-07T18:33:49.766621 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
109518:33:49I, [2024-11-07T18:33:49.770392 #345] INFO -- : Database: 'main', Table: 'project_type_ci_runner_machines_687967fa8a': Lock Writes
109618:33:49I, [2024-11-07T18:33:49.771493 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
109718:33:49I, [2024-11-07T18:33:49.772313 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
109818:33:49I, [2024-11-07T18:33:49.775776 #345] INFO -- : Database: 'main', Table: 'ci_runner_machines_687967fa8a': Lock Writes
109918:33:49I, [2024-11-07T18:33:49.776930 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
110018:33:49I, [2024-11-07T18:33:49.777793 #345] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
110118:34:05# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_incident_management_pending_alert_escalations_project_id_spec.rb. It took 46.45 seconds. Expected to take 22.89 seconds.
110218:34:05# [RSpecRunTime] RSpec elapsed time: 44 minutes 47.0 seconds. Current RSS: ~1263M. Threads: 1. load average: 0.93 0.95 0.99 1/269 426
110318:34:05.
110418:34:05# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_issues_correct_work_item_type_id_spec.rb. Expected to take 12.9 seconds.
110518:34:05Gitlab::BackgroundMigration::BackfillIssuesCorrectWorkItemTypeId
110618:34:11 tracks timings of queries
110718:34:16 sets correct_work_item_type_id for all records in batches
110818:34:27# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_issues_correct_work_item_type_id_spec.rb. It took 21.64 seconds. Expected to take 12.9 seconds.
110918:34:27# [RSpecRunTime] RSpec elapsed time: 45 minutes 8.68 seconds. Current RSS: ~1252M. Threads: 1. load average: 0.89 0.93 0.98 1/269 427
111018:34:27.
111118:34:27# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_default_branch_protection_settings_spec.rb. Expected to take 11.62 seconds.
111218:34:27Gitlab::BackgroundMigration::BackfillDefaultBranchProtectionSettings
111318:34:32 updates default_branch_protection_defaults to a correct value
111418:34:32 when all the namespaces have `default_branch_protection` set
111518:34:36 does not update the settings
111618:34:36# [RSpecRunTime] RSpec elapsed time: 45 minutes 17.91 seconds. Current RSS: ~1262M. Threads: 1. load average: 0.91 0.94 0.98 1/269 428
111718:34:36.
111818:34:46# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_default_branch_protection_settings_spec.rb. It took 19.57 seconds. Expected to take 11.62 seconds.
111918:34:46# [RSpecRunTime] RSpec elapsed time: 45 minutes 28.3 seconds. Current RSS: ~1248M. Threads: 1. load average: 0.92 0.94 0.98 1/269 429
112018:34:46.
112118:34:46# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/fix_namespace_id_for_work_item_parent_links_spec.rb. Expected to take 7.32 seconds.
112218:34:46Gitlab::BackgroundMigration::FixNamespaceIdForWorkItemParentLinks
112318:34:47 #perform
112418:34:52 fixes the namespace_id for work item parent links
112518:34:52# [RSpecRunTime] RSpec elapsed time: 45 minutes 33.55 seconds. Current RSS: ~1263M. Threads: 1. load average: 0.93 0.94 0.98 1/269 430
112618:34:52.
112718:35:02# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/fix_namespace_id_for_work_item_parent_links_spec.rb. It took 15.83 seconds. Expected to take 7.32 seconds.
112818:35:02# [RSpecRunTime] RSpec elapsed time: 45 minutes 44.17 seconds. Current RSS: ~1250M. Threads: 1. load average: 1.01 0.96 0.99 1/269 431
112918:35:02.
113018:35:02# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/resync_has_vulnerabilities_spec.rb. Expected to take 6.77 seconds.
113118:35:02Gitlab::BackgroundMigration::ResyncHasVulnerabilities
113218:35:08 fixes only the incorrect records
113318:35:18# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/resync_has_vulnerabilities_spec.rb. It took 16.09 seconds. Expected to take 6.77 seconds.
113418:35:18# [RSpecRunTime] RSpec elapsed time: 46 minutes 0.3 second. Current RSS: ~1250M. Threads: 1. load average: 1.01 0.96 0.99 1/269 432
113518:35:18.
113618:35:18# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/copy_taggings_to_p_ci_build_tags_spec.rb. Expected to take 6.06 seconds.
113718:35:18Gitlab::BackgroundMigration::CopyTaggingsToPCiBuildTags
113818:35:19 #perform
113918:35:24 copies records over into p_ci_build_tags
114018:35:24# [RSpecRunTime] RSpec elapsed time: 46 minutes 5.74 seconds. Current RSS: ~1271M. Threads: 1. load average: 1.01 0.96 0.99 1/269 433
114118:35:24.
114218:35:34# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/copy_taggings_to_p_ci_build_tags_spec.rb. It took 15.94 seconds. Expected to take 6.06 seconds.
114318:35:34# [RSpecRunTime] RSpec elapsed time: 46 minutes 16.28 seconds. Current RSS: ~1258M. Threads: 1. load average: 0.93 0.95 0.99 1/269 434
114418:35:34.
114518:36:16auto_explain log contains 1157 entries for main, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-background-migration-pg14-5-10.345.main.ndjson.gz
114618:36:16took 41.639503904
114718:36:55auto_explain log contains 1157 entries for ci, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-background-migration-pg14-5-10.345.ci.ndjson.gz
114818:36:55took 39.187017687
114918:36:55[TEST PROF INFO] EventProf results for sql.active_record
115018:36:55Total time: 26:17.935 of 46:05.400 (57.06%)
115118:36:55Total events: 1193968
115218:36:55Top 5 slowest suites (by time):
115318:36:55Gitlab::Backg...dsClusterAgent (./spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb:5) – 02:45.883 (118906 / 3) of 04:55.304 (56.17%)
115418:36:55Gitlab::Backg...erabilityReads (./spec/lib/gitlab/background_migration/backfill_namespace_id_of_vulnerability_reads_spec.rb:5) – 02:34.222 (113875 / 1) of 04:04.738 (63.01%)
115518:36:55Gitlab::Backg...ulnerabilities (./spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb:4) – 02:31.000 (115631 / 2) of 04:08.936 (60.66%)
115618:36:55Gitlab::Backg...ataNamespaceId (./spec/lib/gitlab/background_migration/backfill_issue_search_data_namespace_id_spec.rb:5) – 02:12.790 (96656 / 1) of 03:29.214 (63.47%)
115718:36:55Gitlab::Backg...anizationUsers (./spec/lib/gitlab/background_migration/backfill_default_organization_users_spec.rb:5) – 01:53.741 (88970 / 2) of 03:10.389 (59.74%)
115818:36:55Knapsack report was generated. Preview:
115918:36:55{
116018:36:55 "spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb": 169.959911519,
116118:36:55 "spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb": 127.809158937,
116218:36:55 "spec/lib/gitlab/background_migration/backfill_namespace_id_of_vulnerability_reads_spec.rb": 121.15323995200004,
116318:36:55 "spec/lib/gitlab/background_migration/backfill_default_organization_users_spec.rb": 96.04194482000003,
116418:36:55 "spec/lib/gitlab/background_migration/backfill_issue_search_data_namespace_id_spec.rb": 99.04106501199999,
116518:36:55 "spec/lib/gitlab/background_migration/backfill_work_item_parent_links_namespace_id_spec.rb": 83.8469165800002,
116618:36:55 "spec/lib/gitlab/background_migration/backfill_dora_daily_metrics_project_id_spec.rb": 65.94575612499989,
116718:36:55 "spec/lib/gitlab/background_migration/backfill_dast_site_profile_secret_variables_project_id_spec.rb": 67.99144585299996,
116818:36:55 "spec/lib/gitlab/background_migration/backfill_epic_user_mentions_group_id_spec.rb": 63.021914404999734,
116918:36:55 "spec/lib/gitlab/background_migration/backfill_dast_profiles_tags_project_id_spec.rb": 76.15019012099992,
117018:36:55 "spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb": 63.37816370000019,
117118:36:55 "spec/lib/gitlab/background_migration/backfill_vulnerability_finding_signatures_project_id_spec.rb": 64.29692778199978,
117218:36:55 "spec/lib/gitlab/background_migration/backfill_ci_unit_test_failures_project_id_spec.rb": 48.94147980800017,
117318:36:55 "spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb": 45.6215600139999,
117418:36:55 "spec/lib/gitlab/background_migration/backfill_work_item_hierarchy_for_epics_spec.rb": 41.083762579999984,
117518:36:55 "spec/lib/gitlab/background_migration/backfill_epic_dates_to_work_item_dates_sources_spec.rb": 41.684723943000336,
117618:36:55 "spec/lib/gitlab/background_migration/batching_strategies/loose_index_scan_batching_strategy_spec.rb": 26.981218158000047,
117718:36:55 "spec/lib/gitlab/background_migration/backfill_packages_rpm_metadata_project_id_spec.rb": 21.662935190999633,
117818:36:55 "spec/lib/gitlab/background_migration/backfill_alert_management_alert_metric_images_project_id_spec.rb": 22.08073318300012,
117918:36:55 "spec/lib/gitlab/background_migration/backfill_incident_management_pending_alert_escalations_project_id_spec.rb": 19.745215841000118,
118018:36:55 "spec/lib/gitlab/background_migration/backfill_issues_correct_work_item_type_id_spec.rb": 10.847897733999616,
118118:36:55 "spec/lib/gitlab/background_migration/backfill_default_branch_protection_settings_spec.rb": 9.240859686000022,
118218:36:55 "spec/lib/gitlab/background_migration/fix_namespace_id_for_work_item_parent_links_spec.rb": 5.250057087000187,
118318:36:55 "spec/lib/gitlab/background_migration/resync_has_vulnerabilities_spec.rb": 5.692574736000097,
118418:36:55 "spec/lib/gitlab/background_migration/copy_taggings_to_p_ci_build_tags_spec.rb": 5.462072172000262
118518:36:55}
118618:36:55Knapsack global time execution for tests: 23m 22s
118718:36:55Finished in 47 minutes 37 seconds (files took 1 minute 21.77 seconds to load)
118818:36:5553 examples, 0 failures
118918:36:55Randomized with seed 5718
119018:37:02[TEST PROF INFO] Time spent in factories: 00:00.537 (0.02% of total time)
119118:37:02RSpec exited with 0.
119218:37:02No examples to retry, congrats!
1193 18:37:03 Running after_script 00:10
119418:37:04Running after script...
119518:37:04$ source scripts/utils.sh
119618:37:04$ log_disk_usage
119718:37:04*******************************************************
119818:37:04This runner currently has 78G free disk space.
119918:37:04*******************************************************
1200 18:37:04 Disk usage detail 00:00
125618:37:04$ bundle exec gem list gitlab_quality-test_tooling
125718:37:07gitlab_quality-test_tooling (2.1.0)
125818:37:07$ section_start "failed-test-issues" "Report test failures" # collapsed multi-line command
1259 18:37:07 Report test failures 00:00
126118:37:07$ section_start "flaky-test-issues" "Report test flakiness" # collapsed multi-line command
1262 18:37:07 Report test flakiness 00:00
126418:37:07$ section_start "slow-test-issues" "Report test slowness" # collapsed multi-line command
1265 18:37:07 Report test slowness 00:00
126718:37:07$ section_start "slow-test-merge-request-report-note" "Report test slowness in MR note" # collapsed multi-line command
1268 18:37:07 Report test slowness in MR note 00:03
127118:37:10$ section_start "knapsack-report-issues" "Report test files close to timing out" # collapsed multi-line command
1272 18:37:10 Report test files close to timing out 00:02
127518:37:12$ tooling/bin/push_job_metrics || true
127618:37:13[job-metrics] Pushing job metrics file for the CI/CD job.
127718:37:13[job-metrics] Pushed 4 CI job metric entries to InfluxDB.
1278 18:37:13 Saving cache for successful job 00:01
127918:37:14Not uploading cache ruby-gems-debian-bookworm-ruby-3.2.5-gemfile-Gemfile-20 due to policy
1280 18:37:14 Uploading artifacts for successful job 00:07
128118:37:17Uploading artifacts...
128218:37:17auto_explain/: found 3 matching artifact files and directories
128318:37:17coverage/: found 5 matching artifact files and directories
128418:37:17crystalball/: found 2 matching artifact files and directories
128518:37:17WARNING: deprecations/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
128618:37:17knapsack/: found 4 matching artifact files and directories
128718:37:17rspec/: found 16 matching artifact files and directories
128818:37:17WARNING: tmp/capybara/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
128918:37:17log/*.log: found 13 matching artifact files and directories
129018:37:17WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/8298976130/artifacts?artifact_format=zip&artifact_type=archive&expire_in=31d new-url=https://gitlab.com
129118:37:17WARNING: Retrying... context=artifacts-uploader error=request redirected
129218:37:19Uploading artifacts as "archive" to coordinator... 201 Created id=8298976130 responseStatus=201 Created token=glcbt-66
129318:37:19Uploading artifacts...
129418:37:20rspec/rspec-*.xml: found 1 matching artifact files and directories
129518:37:20WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/8298976130/artifacts?artifact_format=gzip&artifact_type=junit&expire_in=31d new-url=https://gitlab.com
129618:37:20WARNING: Retrying... context=artifacts-uploader error=request redirected
129718:37:21Uploading artifacts as "junit" to coordinator... 201 Created id=8298976130 responseStatus=201 Created token=glcbt-66
1298 18:37:21 Cleaning up project directory and file based variables 00:01
129918:37:29Job succeeded