Skip to content
Snippets Groups Projects

rspec background_migration pg14 8/10

Passed Started by
🤖 GitLab Bot 🤖
@gitlab-bot
1Running with gitlab-runner 17.0.0~pre.88.g761ae5dd (761ae5dd)
2 on green-5.private.runners-manager.gitlab.com/gitlab.com/gitlab-org Zi_8oswQ, system ID: s_8a4f217c24b6
3 feature flags: FF_NETWORK_PER_BUILD:true
4Resolving secrets
5 Preparing the "docker+machine" executor 00:07
6Using Docker executor with image registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14:rubygems-3.4-git-2.36-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 ...
7Starting service registry.gitlab.com/gitlab-org/gitlab-build-images:postgres-14-pgvector-0.4.1 ...
8Authenticating with credentials from job payload (GitLab Registry)
9Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images:postgres-14-pgvector-0.4.1 ...
10Using 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 ...
11WARNING: Service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 is already created. Ignoring.
12WARNING: Service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 is already created. Ignoring.
13Starting service registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 ...
14Authenticating with credentials from job payload (GitLab Registry)
15Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images:redis-cluster-6.2.12 ...
16Using 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 ...
17Starting service redis:6.2-alpine ...
18Pulling docker image redis:6.2-alpine ...
19Using docker image sha256:36c1d3cfe18f4b12d4640576f7048068acbfc3625027b6bbb46bba0e31b11831 for redis:6.2-alpine with digest redis@sha256:e3b17ba9479deec4b7d1eeec1548a253acc5374d68d3b27937fcfe4df8d18c7e ...
20Waiting for services to be up and running (timeout 30 seconds)...
21Authenticating with credentials from job payload (GitLab Registry)
22Pulling docker image registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14:rubygems-3.4-git-2.36-lfs-2.9-chrome-123-yarn-1.22-graphicsmagick-1.3.36 ...
23Using docker image sha256:b26253b493531cada33f45ef568f38c50a310442d05c39f517656e0f7d305dc7 for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14:rubygems-3.4-git-2.36-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.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14@sha256:543339542a02edc250c2c0424c5077b673f1fca2877024fdc5fb670eff44f8cf ...
24 Preparing environment 00:01
25Running on runner-zi8oswq-project-278964-concurrent-0 via runner-zi8oswq-private-1722412207-5c9cd6be...
26 Getting source from Git repository 00:01
27Skipping Git repository setup
28Skipping Git checkout
29Skipping Git submodules setup
30 Restoring cache 00:21
31Checking cache for ruby-gems-debian-bookworm-ruby-3.1.5-17...
32Downloading cache from https://storage.googleapis.com/gitlab-com-runners-cache/project/278964/ruby-gems-debian-bookworm-ruby-3.1.5-17
33Successfully extracted cache
34 Downloading artifacts 00:39
35Downloading artifacts for clone-gitlab-repo (7471344368)...
36Downloading artifacts from coordinator... ok host=storage.googleapis.com id=7471344368 responseStatus=200 OK token=glcbt-66
37WARNING: Part of .git directory is on the list of files to extract
38WARNING: This may introduce unexpected problems
39Downloading artifacts for compile-test-assets (7471344747)...
40Downloading artifacts from coordinator... ok host=storage.googleapis.com id=7471344747 responseStatus=200 OK token=glcbt-66
41Downloading artifacts for retrieve-tests-metadata (7471344898)...
42Downloading artifacts from coordinator... ok host=storage.googleapis.com id=7471344898 responseStatus=200 OK token=glcbt-66
43Downloading artifacts for setup-test-env (7471344810)...
44Downloading artifacts from coordinator... ok host=storage.googleapis.com id=7471344810 responseStatus=200 OK token=glcbt-66
45 Executing "step_script" stage of the job script
46Using docker image sha256:b26253b493531cada33f45ef568f38c50a310442d05c39f517656e0f7d305dc7 for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14:rubygems-3.4-git-2.36-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.1.5-golang-1.22-rust-1.73-node-20.12-postgresql-14@sha256:543339542a02edc250c2c0424c5077b673f1fca2877024fdc5fb670eff44f8cf ...
47$ echo $FOSS_ONLY
48$ [ "$FOSS_ONLY" = "1" ] && rm -rf ee/ qa/spec/ee/ qa/qa/specs/features/ee/ qa/qa/ee/ qa/qa/ee.rb
49$ export GOPATH=$CI_PROJECT_DIR/.go
50$ mkdir -p $GOPATH
51$ source scripts/utils.sh
52$ source scripts/prepare_build.sh
53 Installing gems 00:16
82Using decomposed database config (config/database.yml.decomposed-postgresql)
83Geo DB won't be set up.
84Embedding DB won't be set up.
85 Setting up DBs 01:04
96$ source ./scripts/rspec_helpers.sh
97$ run_timed_command "gem install knapsack --no-document"
98$ gem install knapsack --no-document
99Successfully installed knapsack-4.0.0
1001 gem installed
101==> 'gem install knapsack --no-document' succeeded in 1 seconds.
102$ section_start "gitaly-test-spawn" "Spawning Gitaly"; scripts/gitaly-test-spawn; section_end "gitaly-test-spawn"
103 Spawning Gitaly 00:04
107$ export RSPEC_SKIPPED_TESTS_REPORT_PATH="rspec/skipped_tests-${CI_JOB_ID}.txt"
108$ export RSPEC_RETRIED_TESTS_REPORT_PATH="rspec/retried_tests-${CI_JOB_ID}.txt"
109$ tooling/bin/create_job_metrics_file || true
110[job-metrics] Creating the job metrics file for the CI/CD job.
111$ rspec_section rspec_parallelized_job "--fail-fast=${RSPEC_FAIL_FAST_THRESHOLD} --tag ~quarantine --tag ~zoekt --tag ~click_house"
112 RSpec 27:08
113[10:14:16] Starting rspec_parallelized_job
114RETRY_FAILED_TESTS_IN_NEW_PROCESS: true
115KNAPSACK_GENERATE_REPORT: true
116FLAKY_RSPEC_GENERATE_REPORT: true
117KNAPSACK_TEST_FILE_PATTERN: spec/{lib/gitlab/background_migration,lib/ee/gitlab/background_migration}{,/**/}*_spec.rb
118KNAPSACK_LOG_LEVEL: debug
119KNAPSACK_REPORT_PATH: knapsack/rspec_background_migration_pg14_8_10_278964_report.json
120FLAKY_RSPEC_SUITE_REPORT_PATH: rspec/flaky/report-suite.json
121FLAKY_RSPEC_REPORT_PATH: rspec/flaky/all_rspec_background_migration_pg14_8_10_278964_report.json
122NEW_FLAKY_RSPEC_REPORT_PATH: rspec/flaky/new_rspec_background_migration_pg14_8_10_278964_report.json
123RSPEC_SKIPPED_TESTS_REPORT_PATH: rspec/skipped_tests-7471345491.txt
124CRYSTALBALL: true
125RSPEC_TESTS_MAPPING_ENABLED:
126RSPEC_TESTS_FILTER_FILE:
127Shell set options (set -o) enabled:
128braceexpand on
129hashall on
130interactive-comments on
131pipefail on
132Knapsack report generator started!
133warning: parser/current is loading parser/ruby31, which recognizes 3.1.6-compliant syntax, but you are running 3.1.5.
134Please see https://github.com/whitequark/parser#compatibility-with-ruby-mri.
135Run options: exclude {:quarantine=>true, :zoekt=>true, :click_house=>true}
136# [RSpecRunTime] Starting RSpec timer...
137[TEST PROF INFO] EventProf enabled (sql.active_record)
138unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
139unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
140Test environment set up in 2.075024723 seconds
141# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb. Expected to take 2 minutes 6.94 seconds.
142Gitlab::BackgroundMigration::BackfillVulnerabilityReadsClusterAgent
143 #filter_batch
144 pick only vulnerability reads where report_type = 7
145 #perform
146 backfills `casted_cluster_agent_id` for the selected records
147 tracks timings of queries
148# [RSpecRunTime] RSpec elapsed time: 1 minute 55.12 seconds. Current RSS: ~1458M. Threads: 2. load average: 1.06 1.07 1.03 1/277 403
149.
150INFO: analyzing "public.p_ci_runner_machine_builds" inheritance tree
151INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_100"
152INFO: "ci_runner_machine_builds_100": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
153INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_101"
154INFO: "ci_runner_machine_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
155INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_102"
156INFO: "ci_runner_machine_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
157INFO: analyzing "public.p_ci_job_annotations" inheritance tree
158INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_100"
159INFO: "ci_job_annotations_100": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
160INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_101"
161INFO: "ci_job_annotations_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
162INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_102"
163INFO: "ci_job_annotations_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
164INFO: analyzing "public.p_ci_builds_metadata" inheritance tree
165INFO: analyzing "public.ci_builds_metadata"
166INFO: "ci_builds_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
167INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_101"
168INFO: "ci_builds_metadata_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
169INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_102"
170INFO: "ci_builds_metadata_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
171INFO: analyzing "public.p_ci_builds" inheritance tree
172INFO: analyzing "public.ci_builds"
173INFO: "ci_builds": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
174INFO: analyzing "gitlab_partitions_dynamic.ci_builds_101"
175INFO: "ci_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
176INFO: analyzing "gitlab_partitions_dynamic.ci_builds_102"
177INFO: "ci_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
178I, [2024-07-31T10:18:11.387609 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
179I, [2024-07-31T10:18:30.395393 #325] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
180INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
181INFO: analyzing "public.ci_pipeline_variables"
182INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
183I, [2024-07-31T10:18:31.982174 #325] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
184I, [2024-07-31T10:18:31.983402 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
185I, [2024-07-31T10:18:31.984177 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
186INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
187INFO: analyzing "public.ci_pipeline_variables"
188INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
189INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
190INFO: analyzing "public.ci_job_artifacts"
191INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
192I, [2024-07-31T10:18:37.753330 #325] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
193I, [2024-07-31T10:18:37.754387 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
194I, [2024-07-31T10:18:37.755187 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
195INFO: analyzing "public.p_ci_stages" inheritance tree
196INFO: analyzing "public.ci_stages"
197INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
198I, [2024-07-31T10:18:40.832628 #325] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
199I, [2024-07-31T10:18:40.833624 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
200I, [2024-07-31T10:18:40.834433 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
201I, [2024-07-31T10:18:41.942614 #325] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
202I, [2024-07-31T10:18:47.920103 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
203I, [2024-07-31T10:19:00.616687 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
204I, [2024-07-31T10:19:00.617850 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
205I, [2024-07-31T10:19:00.619020 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
206I, [2024-07-31T10:19:11.286246 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
207I, [2024-07-31T10:19:17.377272 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
208# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb. It took 3 minutes 25.67 seconds. Expected to take 2 minutes 6.94 seconds.
209# [RSpecRunTime] RSpec elapsed time: 3 minutes 30.97 seconds. Current RSS: ~1346M. Threads: 2. load average: 1.02 1.05 1.03 1/278 404
210.
211# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_design_management_repositories_spec.rb. Expected to take 1 minute 51.29 seconds.
212Gitlab::BackgroundMigration::BackfillDesignManagementRepositories
213 #perform
214 creates design_management_repositories entries for all projects in range
215 when project_id already exists in design_management_repositories
216 doesn't duplicate project_id
217# [RSpecRunTime] RSpec elapsed time: 5 minutes 9.64 seconds. Current RSS: ~1429M. Threads: 2. load average: 1.10 1.09 1.04 1/278 405
218.
219INFO: analyzing "public.p_ci_runner_machine_builds" inheritance tree
220INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_100"
221INFO: "ci_runner_machine_builds_100": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
222INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_101"
223INFO: "ci_runner_machine_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
224INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_102"
225INFO: "ci_runner_machine_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
226INFO: analyzing "public.p_ci_job_annotations" inheritance tree
227INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_100"
228INFO: "ci_job_annotations_100": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
229INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_101"
230INFO: "ci_job_annotations_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
231INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_102"
232INFO: "ci_job_annotations_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
233INFO: analyzing "public.p_ci_builds_metadata" inheritance tree
234INFO: analyzing "public.ci_builds_metadata"
235INFO: "ci_builds_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
236INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_101"
237INFO: "ci_builds_metadata_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
238INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_102"
239INFO: "ci_builds_metadata_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
240INFO: analyzing "public.p_ci_builds" inheritance tree
241INFO: analyzing "public.ci_builds"
242INFO: "ci_builds": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
243INFO: analyzing "gitlab_partitions_dynamic.ci_builds_101"
244INFO: "ci_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
245INFO: analyzing "gitlab_partitions_dynamic.ci_builds_102"
246INFO: "ci_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
247I, [2024-07-31T10:21:24.015021 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
248I, [2024-07-31T10:21:43.005511 #325] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
249INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
250INFO: analyzing "public.ci_pipeline_variables"
251INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
252I, [2024-07-31T10:21:44.601295 #325] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
253I, [2024-07-31T10:21:44.602368 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
254I, [2024-07-31T10:21:44.603687 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
255INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
256INFO: analyzing "public.ci_pipeline_variables"
257INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
258INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
259INFO: analyzing "public.ci_job_artifacts"
260INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
261I, [2024-07-31T10:21:50.244982 #325] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
262I, [2024-07-31T10:21:50.246155 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
263I, [2024-07-31T10:21:50.246993 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
264INFO: analyzing "public.p_ci_stages" inheritance tree
265INFO: analyzing "public.ci_stages"
266INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
267I, [2024-07-31T10:21:53.497573 #325] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
268I, [2024-07-31T10:21:53.499263 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
269I, [2024-07-31T10:21:53.500130 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
270I, [2024-07-31T10:21:54.677382 #325] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
271I, [2024-07-31T10:22:00.901478 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
272I, [2024-07-31T10:22:13.759127 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
273I, [2024-07-31T10:22:13.760339 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
274I, [2024-07-31T10:22:13.761130 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
275I, [2024-07-31T10:22:24.996208 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
276I, [2024-07-31T10:22:31.539042 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
277# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_design_management_repositories_spec.rb. It took 3 minutes 14.28 seconds. Expected to take 1 minute 51.29 seconds.
278# [RSpecRunTime] RSpec elapsed time: 6 minutes 45.3 seconds. Current RSS: ~1370M. Threads: 2. load average: 0.81 1.00 1.01 1/278 406
279.
280# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb. Expected to take 1 minute 32.15 seconds.
281Gitlab::BackgroundMigration::BackfillFindingIdInVulnerabilities
282 #perform
283 backfills finding_id column in the vulnerabilities table
284 does not affect rows with finding_id populated
285# [RSpecRunTime] RSpec elapsed time: 8 minutes 10.93 seconds. Current RSS: ~1444M. Threads: 2. load average: 0.95 1.01 1.01 2/278 407
286.
287I, [2024-07-31T10:24:08.767725 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
288I, [2024-07-31T10:24:30.959206 #325] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
289INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
290INFO: analyzing "public.ci_pipeline_variables"
291INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
292I, [2024-07-31T10:24:32.819209 #325] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
293I, [2024-07-31T10:24:32.820964 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
294I, [2024-07-31T10:24:32.821897 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
295INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
296INFO: analyzing "public.ci_pipeline_variables"
297INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
298INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
299INFO: analyzing "public.ci_job_artifacts"
300INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
301I, [2024-07-31T10:24:39.526493 #325] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
302I, [2024-07-31T10:24:39.528016 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
303I, [2024-07-31T10:24:39.528951 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
304INFO: analyzing "public.p_ci_stages" inheritance tree
305INFO: analyzing "public.ci_stages"
306INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
307I, [2024-07-31T10:24:43.076685 #325] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
308I, [2024-07-31T10:24:43.077913 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
309I, [2024-07-31T10:24:43.078725 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
310I, [2024-07-31T10:24:44.263347 #325] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
311I, [2024-07-31T10:24:50.845981 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
312I, [2024-07-31T10:25:04.407103 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
313I, [2024-07-31T10:25:04.408472 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
314I, [2024-07-31T10:25:04.409876 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
315I, [2024-07-31T10:25:16.532690 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
316I, [2024-07-31T10:25:23.923421 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
317# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb. It took 2 minutes 53.17 seconds. Expected to take 1 minute 32.15 seconds.
318# [RSpecRunTime] RSpec elapsed time: 9 minutes 38.52 seconds. Current RSS: ~1351M. Threads: 2. load average: 0.96 0.99 1.00 1/279 408
319.
320# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_partition_id_ci_pipeline_chat_data_spec.rb. Expected to take 1 minute 12.39 seconds.
321Gitlab::BackgroundMigration::BackfillPartitionIdCiPipelineChatData
322 #perform
323 when second partition does not exist
324 does not execute the migration
325# [RSpecRunTime] RSpec elapsed time: 10 minutes 43.28 seconds. Current RSS: ~1414M. Threads: 2. load average: 1.16 1.05 1.02 1/279 409
326.
327 when second partition exists
328 fixes invalid records in the wrong the partition
329# [RSpecRunTime] RSpec elapsed time: 10 minutes 50.19 seconds. Current RSS: ~1448M. Threads: 2. load average: 1.15 1.05 1.02 1/279 410
330.
331I, [2024-07-31T10:26:50.000164 #325] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
332INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
333INFO: analyzing "public.ci_pipeline_variables"
334INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
335I, [2024-07-31T10:26:51.826485 #325] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
336I, [2024-07-31T10:26:51.827646 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
337I, [2024-07-31T10:26:51.828482 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
338INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
339INFO: analyzing "public.ci_pipeline_variables"
340INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
341INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
342INFO: analyzing "public.ci_job_artifacts"
343INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
344I, [2024-07-31T10:26:58.516649 #325] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
345I, [2024-07-31T10:26:58.517932 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
346I, [2024-07-31T10:26:58.518777 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
347INFO: analyzing "public.p_ci_stages" inheritance tree
348INFO: analyzing "public.ci_stages"
349INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
350I, [2024-07-31T10:27:02.193497 #325] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
351I, [2024-07-31T10:27:02.238570 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
352I, [2024-07-31T10:27:02.239693 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
353I, [2024-07-31T10:27:03.499162 #325] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
354I, [2024-07-31T10:27:09.927005 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
355I, [2024-07-31T10:27:23.758495 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
356I, [2024-07-31T10:27:23.759681 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
357I, [2024-07-31T10:27:23.760467 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
358I, [2024-07-31T10:27:34.919952 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
359I, [2024-07-31T10:27:41.155164 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
360# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_partition_id_ci_pipeline_chat_data_spec.rb. It took 2 minutes 16.1 seconds. Expected to take 1 minute 12.39 seconds.
361# [RSpecRunTime] RSpec elapsed time: 11 minutes 54.69 seconds. Current RSS: ~1356M. Threads: 2. load average: 1.06 1.04 1.01 2/280 411
362.
363# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_default_organization_owners_again_spec.rb. Expected to take 1 minute 3.75 seconds.
364Gitlab::BackgroundMigration::BackfillDefaultOrganizationOwnersAgain
365 #perform
366 with no entries for admin user in organization_users
367 adds admins correctly with the default organization to organization_users
368# [RSpecRunTime] RSpec elapsed time: 12 minutes 47.32 seconds. Current RSS: ~1434M. Threads: 2. load average: 1.07 1.05 1.01 1/280 412
369.
370 when admin already exists in organization_users as a default user
371 updates the organization_users entry to owner
372# [RSpecRunTime] RSpec elapsed time: 12 minutes 53.14 seconds. Current RSS: ~1430M. Threads: 2. load average: 1.14 1.06 1.02 1/280 413
373.
374INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
375INFO: analyzing "public.ci_pipeline_variables"
376INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
377INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
378INFO: analyzing "public.ci_job_artifacts"
379INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
380I, [2024-07-31T10:28:56.270426 #325] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
381I, [2024-07-31T10:28:56.271500 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
382I, [2024-07-31T10:28:56.272345 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
383INFO: analyzing "public.p_ci_stages" inheritance tree
384INFO: analyzing "public.ci_stages"
385INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
386I, [2024-07-31T10:28:59.768261 #325] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
387I, [2024-07-31T10:28:59.769342 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
388I, [2024-07-31T10:28:59.770154 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
389I, [2024-07-31T10:29:00.820149 #325] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
390I, [2024-07-31T10:29:06.709581 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
391I, [2024-07-31T10:29:19.585630 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
392I, [2024-07-31T10:29:19.586731 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
393I, [2024-07-31T10:29:19.587467 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
394I, [2024-07-31T10:29:30.322041 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
395I, [2024-07-31T10:29:36.344091 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
396# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_default_organization_owners_again_spec.rb. It took 1 minute 54.89 seconds. Expected to take 1 minute 3.75 seconds.
397# [RSpecRunTime] RSpec elapsed time: 13 minutes 49.63 seconds. Current RSS: ~1357M. Threads: 2. load average: 0.99 1.03 1.01 1/280 414
398.
399# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_has_issues_for_external_issue_links_spec.rb. Expected to take 48.93 seconds.
400Gitlab::BackgroundMigration::BackfillHasIssuesForExternalIssueLinks
401 sets has_issues of an existing record
402 when there exists a record with has_issues
403 does not modify existing records with has_issues
404# [RSpecRunTime] RSpec elapsed time: 14 minutes 34.63 seconds. Current RSS: ~1463M. Threads: 2. load average: 1.09 1.06 1.01 1/280 415
405.
406I, [2024-07-31T10:30:35.487338 #325] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
407I, [2024-07-31T10:30:48.773062 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
408I, [2024-07-31T10:30:48.774346 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
409I, [2024-07-31T10:30:48.775750 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
410I, [2024-07-31T10:31:00.195645 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
411I, [2024-07-31T10:31:06.598904 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
412# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_has_issues_for_external_issue_links_spec.rb. It took 1 minute 30.58 seconds. Expected to take 48.93 seconds.
413# [RSpecRunTime] RSpec elapsed time: 15 minutes 20.26 seconds. Current RSS: ~1345M. Threads: 2. load average: 1.04 1.05 1.01 1/280 416
414.
415# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb. Expected to take 37.02 seconds.
416Gitlab::BackgroundMigration::CopyColumnUsingBackgroundMigrationJob
417 is expected to be < Gitlab::BackgroundMigration::BatchedMigrationJob
418 #perform
419 tracks timings of queries
420 primary keys
421 copies all in range
422# [RSpecRunTime] RSpec elapsed time: 15 minutes 31.92 seconds. Current RSS: ~1496M. Threads: 2. load average: 0.96 1.03 1.00 1/280 417
423.
424 foreign keys
425 copies all in range
426# [RSpecRunTime] RSpec elapsed time: 15 minutes 35.63 seconds. Current RSS: ~1495M. Threads: 2. load average: 0.96 1.03 1.00 1/280 418
427.
428 columns with NULLs
429 copies all in range
430# [RSpecRunTime] RSpec elapsed time: 15 minutes 40.48 seconds. Current RSS: ~1497M. Threads: 2. load average: 0.96 1.03 1.00 1/280 419
431.
432 when multiple columns are given
433 copies all values in the range
434 when the number of source and target columns does not match
435 raises an error
436# [RSpecRunTime] RSpec elapsed time: 15 minutes 47.96 seconds. Current RSS: ~1519M. Threads: 2. load average: 1.05 1.04 1.01 1/280 420
437.
438 pause interval between sub-batches
439 sleeps for the specified time between sub-batches
440 when pause_ms value is negative
441 treats it as a 0
442# [RSpecRunTime] RSpec elapsed time: 15 minutes 55.49 seconds. Current RSS: ~1499M. Threads: 2. load average: 1.04 1.04 1.01 1/280 421
443.
444# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb. It took 42.65 seconds. Expected to take 37.02 seconds.
445# [RSpecRunTime] RSpec elapsed time: 16 minutes 2.96 seconds. Current RSS: ~1426M. Threads: 2. load average: 0.96 1.03 1.00 1/280 422
446.
447# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_vulnerability_merge_request_links_project_id_spec.rb. Expected to take 31.44 seconds.
448Gitlab::BackgroundMigration::BackfillVulnerabilityMergeRequestLinksProjectId
449 performs without error
450 constructs a valid query
451I, [2024-07-31T10:32:40.861879 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
452I, [2024-07-31T10:32:47.370058 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
453# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_vulnerability_merge_request_links_project_id_spec.rb. It took 58.07 seconds. Expected to take 31.44 seconds.
454# [RSpecRunTime] RSpec elapsed time: 17 minutes 1.09 seconds. Current RSS: ~1366M. Threads: 2. load average: 1.15 1.07 1.01 1/280 423
455.
456# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_issue_links_namespace_id_spec.rb. Expected to take 30.69 seconds.
457Gitlab::BackgroundMigration::BackfillIssueLinksNamespaceId
458 constructs a valid query
459 performs without error
460I, [2024-07-31T10:33:36.302350 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
461I, [2024-07-31T10:33:42.663291 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
462# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_issue_links_namespace_id_spec.rb. It took 54.88 seconds. Expected to take 30.69 seconds.
463# [RSpecRunTime] RSpec elapsed time: 17 minutes 56.02 seconds. Current RSS: ~1358M. Threads: 2. load average: 1.17 1.08 1.02 1/280 424
464.
465# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_sbom_occurrences_vulnerabilities_project_id_spec.rb. Expected to take 30.1 seconds.
466Gitlab::BackgroundMigration::BackfillSbomOccurrencesVulnerabilitiesProjectId
467 constructs a valid query
468 performs without error
469I, [2024-07-31T10:34:32.065538 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
470I, [2024-07-31T10:34:38.352585 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
471# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_sbom_occurrences_vulnerabilities_project_id_spec.rb. It took 55.8 seconds. Expected to take 30.1 seconds.
472# [RSpecRunTime] RSpec elapsed time: 18 minutes 51.88 seconds. Current RSS: ~1359M. Threads: 2. load average: 0.96 1.04 1.00 1/280 425
473.
474# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_dast_pre_scan_verifications_project_id_spec.rb. Expected to take 28.97 seconds.
475Gitlab::BackgroundMigration::BackfillDastPreScanVerificationsProjectId
476 performs without error
477 constructs a valid query
478I, [2024-07-31T10:35:17.468706 #325] INFO -- : Database: 'main', Table: 'p_ci_build_sources': Lock Writes
479I, [2024-07-31T10:35:17.469867 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
480I, [2024-07-31T10:35:17.470715 #325] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
481I, [2024-07-31T10:35:28.346969 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
482I, [2024-07-31T10:35:34.541302 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
483# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_dast_pre_scan_verifications_project_id_spec.rb. It took 56.07 seconds. Expected to take 28.97 seconds.
484# [RSpecRunTime] RSpec elapsed time: 19 minutes 48.0 seconds. Current RSS: ~1359M. Threads: 2. load average: 0.97 1.04 1.00 1/280 426
485.
486# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb. Expected to take 19.76 seconds.
487Gitlab::BackgroundMigration::BackfillCatalogResourceVersionSemVer
488 updates the semver columns with the expected values
489I, [2024-07-31T10:36:11.164646 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
490I, [2024-07-31T10:36:17.524414 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
491# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb. It took 43.32 seconds. Expected to take 19.76 seconds.
492# [RSpecRunTime] RSpec elapsed time: 20 minutes 31.37 seconds. Current RSS: ~1355M. Threads: 2. load average: 0.99 1.03 1.00 1/280 427
493.
494# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_vulnerability_flags_project_id_spec.rb. Expected to take 18.25 seconds.
495Gitlab::BackgroundMigration::BackfillVulnerabilityFlagsProjectId
496 constructs a valid query
497 performs without error
498I, [2024-07-31T10:36:46.113498 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
499I, [2024-07-31T10:36:53.233485 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
500# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_vulnerability_flags_project_id_spec.rb. It took 35.33 seconds. Expected to take 18.25 seconds.
501# [RSpecRunTime] RSpec elapsed time: 21 minutes 6.75 seconds. Current RSS: ~1352M. Threads: 2. load average: 0.96 1.01 1.00 1/280 428
502.
503# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_merge_requests_closing_issues_project_id_spec.rb. Expected to take 17.45 seconds.
504Gitlab::BackgroundMigration::BackfillMergeRequestsClosingIssuesProjectId
505 constructs a valid query
506 performs without error
507I, [2024-07-31T10:37:21.177835 #325] INFO -- : Database: 'main', Table: 'p_ci_finished_pipeline_ch_sync_events': Lock Writes
508I, [2024-07-31T10:37:28.498912 #325] INFO -- : Database: 'main', Table: 'p_ci_build_tags': Lock Writes
509# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_merge_requests_closing_issues_project_id_spec.rb. It took 35.13 seconds. Expected to take 17.45 seconds.
510# [RSpecRunTime] RSpec elapsed time: 21 minutes 41.94 seconds. Current RSS: ~1356M. Threads: 2. load average: 1.05 1.04 1.00 1/279 429
511.
512# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_user_details_spec.rb. Expected to take 13.44 seconds.
513Gitlab::BackgroundMigration::BackfillUserDetails
514 #perform
515 creates only the needed user_details entries
516 when there are no user_details that are missing for user records
517 creates only the needed user_details entries
518# [RSpecRunTime] RSpec elapsed time: 21 minutes 50.8 seconds. Current RSS: ~1488M. Threads: 2. load average: 1.04 1.04 1.00 1/279 430
519.
520 when upsert raises an error
521 logs the error
522# [RSpecRunTime] RSpec elapsed time: 21 minutes 55.01 seconds. Current RSS: ~1505M. Threads: 2. load average: 1.04 1.04 1.00 1/279 431
523.
524# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_user_details_spec.rb. It took 22.05 seconds. Expected to take 13.44 seconds.
525# [RSpecRunTime] RSpec elapsed time: 22 minutes 4.04 seconds. Current RSS: ~1418M. Threads: 2. load average: 1.04 1.04 1.00 1/279 432
526.
527# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/backfill_approvals_project_id_spec.rb. Expected to take 11.15 seconds.
528Gitlab::BackgroundMigration::BackfillApprovalsProjectId
529 constructs a valid query
530 performs without error
531# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/backfill_approvals_project_id_spec.rb. It took 21.39 seconds. Expected to take 11.15 seconds.
532# [RSpecRunTime] RSpec elapsed time: 22 minutes 25.48 seconds. Current RSS: ~1363M. Threads: 2. load average: 1.19 1.06 1.01 1/279 433
533.
534# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/update_sbom_components_name_based_on_pep503_spec.rb. Expected to take 8.28 seconds.
535Gitlab::BackgroundMigration::UpdateSbomComponentsNameBasedOnPep503
536 #perform
537 successfully updates name according to PEP 0503
538 with existing record in regards to name, purl_type and component_type
539 raises ActiveRecord::RecordNotUnique
540# [RSpecRunTime] RSpec elapsed time: 22 minutes 33.27 seconds. Current RSS: ~1475M. Threads: 2. load average: 1.16 1.06 1.01 1/279 434
541.
542# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/update_sbom_components_name_based_on_pep503_spec.rb. It took 14.91 seconds. Expected to take 8.28 seconds.
543# [RSpecRunTime] RSpec elapsed time: 22 minutes 40.45 seconds. Current RSS: ~1400M. Threads: 2. load average: 1.14 1.06 1.01 1/279 435
544.
545# [RSpecRunTime] Starting example group spec/lib/gitlab/background_migration/batching_strategies/dismissed_vulnerabilities_strategy_spec.rb. Expected to take 4.67 seconds.
546Gitlab::BackgroundMigration::BatchingStrategies::DismissedVulnerabilitiesStrategy#next_batch
547 is expected to be < Gitlab::BackgroundMigration::BatchingStrategies::PrimaryKeyBatchingStrategy
548# [RSpecRunTime] Finishing example group spec/lib/gitlab/background_migration/batching_strategies/dismissed_vulnerabilities_strategy_spec.rb. It took 12.14 seconds. Expected to take 4.67 seconds.
549# [RSpecRunTime] RSpec elapsed time: 22 minutes 52.64 seconds. Current RSS: ~1396M. Threads: 2. load average: 1.11 1.06 1.01 1/279 436
550.
551auto_explain log contains 1017 entries for main, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-background-migration-pg14-8-10.325.main.ndjson.gz
552took 28.962294999
553auto_explain log contains 1018 entries for ci, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-background-migration-pg14-8-10.325.ci.ndjson.gz
554took 26.987006692
555[TEST PROF INFO] EventProf results for sql.active_record
556Total time: 15:05.276 of 22:47.344 (66.21%)
557Total events: 717065
558Top 5 slowest suites (by time):
559Gitlab::Backg...dsClusterAgent (./spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb:5) – 02:18.431 (99166 / 3) of 03:25.678 (67.3%)
560Gitlab::Backg...ntRepositories (./spec/lib/gitlab/background_migration/backfill_design_management_repositories_spec.rb:9) – 02:16.912 (96446 / 2) of 03:14.333 (70.45%)
561Gitlab::Backg...ulnerabilities (./spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb:4) – 01:59.670 (87881 / 2) of 02:53.225 (69.08%)
562Gitlab::Backg...pelineChatData (./spec/lib/gitlab/background_migration/backfill_partition_id_ci_pipeline_chat_data_spec.rb:5) – 01:34.033 (71289 / 2) of 02:16.155 (69.06%)
563Gitlab::Backg...ionOwnersAgain (./spec/lib/gitlab/background_migration/backfill_default_organization_owners_again_spec.rb:5) – 01:20.318 (66730 / 2) of 01:54.942 (69.88%)
564Knapsack report was generated. Preview:
565{
566 "spec/lib/gitlab/background_migration/backfill_vulnerability_reads_cluster_agent_spec.rb": 111.3726242770008,
567 "spec/lib/gitlab/background_migration/backfill_design_management_repositories_spec.rb": 98.79776033200142,
568 "spec/lib/gitlab/background_migration/backfill_finding_id_in_vulnerabilities_spec.rb": 85.76535026000056,
569 "spec/lib/gitlab/background_migration/backfill_partition_id_ci_pipeline_chat_data_spec.rb": 71.78946105100113,
570 "spec/lib/gitlab/background_migration/backfill_default_organization_owners_again_spec.rb": 58.58388351100075,
571 "spec/lib/gitlab/background_migration/backfill_has_issues_for_external_issue_links_spec.rb": 45.135760814000605,
572 "spec/lib/gitlab/background_migration/copy_column_using_background_migration_job_spec.rb": 35.36036504599906,
573 "spec/lib/gitlab/background_migration/backfill_vulnerability_merge_request_links_project_id_spec.rb": 28.982206737000524,
574 "spec/lib/gitlab/background_migration/backfill_issue_links_namespace_id_spec.rb": 28.032722238000133,
575 "spec/lib/gitlab/background_migration/backfill_sbom_occurrences_vulnerabilities_project_id_spec.rb": 27.677888235000864,
576 "spec/lib/gitlab/background_migration/backfill_dast_pre_scan_verifications_project_id_spec.rb": 28.324000935001095,
577 "spec/lib/gitlab/background_migration/backfill_catalog_resource_version_sem_ver_spec.rb": 18.558180903999528,
578 "spec/lib/gitlab/background_migration/backfill_vulnerability_flags_project_id_spec.rb": 16.810341450000124,
579 "spec/lib/gitlab/background_migration/backfill_merge_requests_closing_issues_project_id_spec.rb": 16.761840336001114,
580 "spec/lib/gitlab/background_migration/backfill_user_details_spec.rb": 13.249518880000323,
581 "spec/lib/gitlab/background_migration/backfill_approvals_project_id_spec.rb": 10.366280129001098,
582 "spec/lib/gitlab/background_migration/update_sbom_components_name_based_on_pep503_spec.rb": 7.907784087999971,
583 "spec/lib/gitlab/background_migration/batching_strategies/dismissed_vulnerabilities_strategy_spec.rb": 5.370517217999804
584}
585Knapsack global time execution for tests: 11m 48s
586Finished in 23 minutes 50 seconds (files took 1 minute 36.91 seconds to load)
58743 examples, 0 failures
588Randomized with seed 47829
589[TEST PROF INFO] Time spent in factories: 00:00.281 (0.02% of total time)
590RSpec exited with 0.
591No examples to retry, congrats!
592 Running after_script 00:10
593Running after script...
594$ source scripts/utils.sh
595$ bundle exec gem list gitlab_quality-test_tooling
596gitlab_quality-test_tooling (1.33.0)
597$ section_start "failed-test-issues" "Report test failures" # collapsed multi-line command
598 Report test failures 00:02
601$ section_start "flaky-test-issues" "Report test flakiness" # collapsed multi-line command
602 Report test flakiness 00:00
604$ section_start "slow-test-issues" "Report test slowness" # collapsed multi-line command
605 Report test slowness 00:02
608$ section_start "slow-test-merge-request-report-note" "Report test slowness in MR note" # collapsed multi-line command
609 Report test slowness in MR note 00:00
611$ section_start "knapsack-report-issues" "Report test files close to timing out" # collapsed multi-line command
612 Report test files close to timing out 00:02
615$ tooling/bin/push_job_metrics || true
616[job-metrics] Pushing job metrics file for the CI/CD job.
617[job-metrics] Pushed 4 CI job metric entries to InfluxDB.
618 Saving cache for successful job 00:01
619Not uploading cache ruby-gems-debian-bookworm-ruby-3.1.5-17 due to policy
620 Uploading artifacts for successful job 00:04
621Uploading artifacts...
622auto_explain/: found 3 matching artifact files and directories
623coverage/: found 5 matching artifact files and directories
624crystalball/: found 5 matching artifact files and directories
625WARNING: deprecations/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
626knapsack/: found 4 matching artifact files and directories
627rspec/: found 12 matching artifact files and directories
628WARNING: tmp/capybara/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
629log/*.log: found 13 matching artifact files and directories
630WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/7471345491/artifacts?artifact_format=zip&artifact_type=archive&expire_in=31d new-url=https://gitlab.com
631WARNING: Retrying... context=artifacts-uploader error=request redirected
632Uploading artifacts as "archive" to coordinator... 201 Created id=7471345491 responseStatus=201 Created token=glcbt-66
633Uploading artifacts...
634rspec/rspec-*.xml: found 1 matching artifact files and directories
635WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/7471345491/artifacts?artifact_format=gzip&artifact_type=junit&expire_in=31d new-url=https://gitlab.com
636WARNING: Retrying... context=artifacts-uploader error=request redirected
637Uploading artifacts as "junit" to coordinator... 201 Created id=7471345491 responseStatus=201 Created token=glcbt-66
638 Cleaning up project directory and file based variables 00:01
639Job succeeded