Skip to content
Snippets Groups Projects

rspec migration pg14 13/15

Passed Started by
Krasimir Angelov
@krasio
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.2.patched-golang-1.21-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:0fc0b666ef9eb249e61edd4e2ec434a328e98117079727c5e7cf6dc9a00d7a94 for redis:6.2-alpine with digest redis@sha256:c6abddbb4223951cf5cb54a19d4a83418582fa69c97c0458ab4f0974f24f119c ...
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.2.patched-golang-1.21-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:d10d211334d3c94a5e626cf961467431b7d3f3bd8b6109e5caf9357421c0117b for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.patched-golang-1.21-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.2.patched-golang-1.21-rust-1.73-node-20.12-postgresql-14@sha256:3c4cd9a237deb59350b4836552151ba2aae96247034074c8f0c2ccaff4558cab ...
24 Preparing environment 00:01
25Running on runner-zi8oswq-project-278964-concurrent-0 via runner-zi8oswq-private-1717022337-ba3f3277...
26 Getting source from Git repository 00:00
27Skipping Git repository setup
28Skipping Git checkout
29Skipping Git submodules setup
30 Restoring cache 00:17
31Checking cache for ruby-gems-debian-bookworm-ruby-3.2-17...
32cache.zip is up to date
33Successfully extracted cache
34 Downloading artifacts 00:46
35Downloading artifacts for clone-gitlab-repo (6975007209)...
36Downloading artifacts from coordinator... ok host=storage.googleapis.com id=6975007209 responseStatus=200 OK token=glcbt-65
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 (6975007223)...
40Downloading artifacts from coordinator... ok host=storage.googleapis.com id=6975007223 responseStatus=200 OK token=glcbt-65
41Downloading artifacts for detect-tests (6975007229)...
42Downloading artifacts from coordinator... ok host=storage.googleapis.com id=6975007229 responseStatus=200 OK token=glcbt-65
43Downloading artifacts for retrieve-tests-metadata (6975007235)...
44Downloading artifacts from coordinator... ok host=storage.googleapis.com id=6975007235 responseStatus=200 OK token=glcbt-65
45Downloading artifacts for setup-test-env (6975007225)...
46Downloading artifacts from coordinator... ok host=storage.googleapis.com id=6975007225 responseStatus=200 OK token=glcbt-65
47 Executing "step_script" stage of the job script
48Using docker image sha256:d10d211334d3c94a5e626cf961467431b7d3f3bd8b6109e5caf9357421c0117b for registry.gitlab.com/gitlab-org/gitlab-build-images/debian-bookworm-ruby-3.2.patched-golang-1.21-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.2.patched-golang-1.21-rust-1.73-node-20.12-postgresql-14@sha256:3c4cd9a237deb59350b4836552151ba2aae96247034074c8f0c2ccaff4558cab ...
49$ echo $FOSS_ONLY
50$ [ "$FOSS_ONLY" = "1" ] && rm -rf ee/ qa/spec/ee/ qa/qa/specs/features/ee/ qa/qa/ee/ qa/qa/ee.rb
51$ export GOPATH=$CI_PROJECT_DIR/.go
52$ mkdir -p $GOPATH
53$ source scripts/utils.sh
54$ source scripts/prepare_build.sh
55 Installing gems 00:17
755Using decomposed database config (config/database.yml.decomposed-postgresql)
756Geo DB won't be set up.
757Embedding DB won't be set up.
758 Setting up DBs 01:14
769$ source ./scripts/rspec_helpers.sh
770$ run_timed_command "gem install knapsack --no-document"
771$ gem install knapsack --no-document
772Successfully installed knapsack-4.0.0
7731 gem installed
774$ section_start "gitaly-test-spawn" "Spawning Gitaly"; scripts/gitaly-test-spawn; section_end "gitaly-test-spawn"
775==> 'gem install knapsack --no-document' succeeded in 1 seconds.
776 Spawning Gitaly 00:04
780$ export RSPEC_SKIPPED_TESTS_REPORT_PATH="rspec/skipped_tests-${CI_JOB_ID}.txt"
781$ export RSPEC_RETRIED_TESTS_REPORT_PATH="rspec/retried_tests-${CI_JOB_ID}.txt"
782$ tooling/bin/create_job_metrics_file || true
783[job-metrics] Creating the job metrics file for the CI/CD job.
784$ rspec_section rspec_parallelized_job "--fail-fast=${RSPEC_FAIL_FAST_THRESHOLD} --tag ~quarantine --tag ~zoekt --tag ~click_house"
785 RSpec 31:17
786[23:31:54] Starting rspec_parallelized_job
787RETRY_FAILED_TESTS_IN_NEW_PROCESS: true
788KNAPSACK_GENERATE_REPORT: true
789FLAKY_RSPEC_GENERATE_REPORT: true
790KNAPSACK_TEST_FILE_PATTERN: spec/{migrations}{,/**/}*_spec.rb
791KNAPSACK_LOG_LEVEL: debug
792KNAPSACK_REPORT_PATH: knapsack/rspec_migration_pg14_13_15_278964_report.json
793FLAKY_RSPEC_SUITE_REPORT_PATH: rspec/flaky/report-suite.json
794FLAKY_RSPEC_REPORT_PATH: rspec/flaky/all_rspec_migration_pg14_13_15_278964_report.json
795NEW_FLAKY_RSPEC_REPORT_PATH: rspec/flaky/new_rspec_migration_pg14_13_15_278964_report.json
796RSPEC_SKIPPED_TESTS_REPORT_PATH: rspec/skipped_tests-6975007391.txt
797CRYSTALBALL:
798RSPEC_TESTS_MAPPING_ENABLED:
799RSPEC_TESTS_FILTER_FILE:
800Shell set options (set -o) enabled:
801braceexpand on
802hashall on
803interactive-comments on
804pipefail on
805Knapsack report generator started!
806warning: parser/current is loading parser/ruby32, which recognizes 3.2.3-compliant syntax, but you are running 3.2.4.
807Please see https://github.com/whitequark/parser#compatibility-with-ruby-mri.
808Run options: exclude {:quarantine=>true, :zoekt=>true, :click_house=>true}
809# [RSpecRunTime] Starting RSpec timer...
810[TEST PROF INFO] EventProf enabled (sql.active_record)
811unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
812unknown OID 2249: failed to recognize type of 'pg_stat_file'. It will be treated as String.
813Test environment set up in 0.707154557 seconds
814# [RSpecRunTime] Starting example group spec/migrations/20230814144045_swap_timelogs_note_id_to_bigint_for_self_hosts_spec.rb. Expected to take 3 minutes 25.41 seconds.
815SwapTimelogsNoteIdToBigintForSelfHosts
816 #up
817 when GitLab.com, dev, or test
818 behaves like column `note_id_convert_to_bigint` is already dropped
819 does not swaps the columns
820 when self-managed instance with the `note_id_convert_to_bigint` column already dropped
821 behaves like column `note_id_convert_to_bigint` is already dropped
822 does not swaps the columns
823# [RSpecRunTime] RSpec elapsed time: 2 minutes 56.26 seconds. Current RSS: ~1098M. Threads: 2. load average: 1.00 0.98 0.94 1/288 393
824.
825 when self-managed instance columns already swapped
826 does not swaps the columns
827# [RSpecRunTime] RSpec elapsed time: 3 minutes 17.79 seconds. Current RSS: ~1090M. Threads: 2. load average: 1.08 1.00 0.95 1/288 394
828.
829 when self-managed instance
830 swaps the columns
831# [RSpecRunTime] RSpec elapsed time: 3 minutes 57.05 seconds. Current RSS: ~1102M. Threads: 2. load average: 1.04 1.00 0.95 1/288 395
832.
833INFO: analyzing "public.p_ci_runner_machine_builds" inheritance tree
834INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_100"
835INFO: "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
836INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_101"
837INFO: "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
838INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_102"
839INFO: "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
840INFO: analyzing "public.p_ci_job_annotations" inheritance tree
841INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_100"
842INFO: "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
843INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_101"
844INFO: "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
845INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_102"
846INFO: "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
847INFO: analyzing "public.p_ci_builds_metadata" inheritance tree
848INFO: analyzing "public.ci_builds_metadata"
849INFO: "ci_builds_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
850INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_101"
851INFO: "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
852INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_102"
853INFO: "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
854INFO: analyzing "public.p_ci_builds" inheritance tree
855INFO: analyzing "public.ci_builds"
856INFO: "ci_builds": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
857INFO: analyzing "gitlab_partitions_dynamic.ci_builds_101"
858INFO: "ci_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
859INFO: analyzing "gitlab_partitions_dynamic.ci_builds_102"
860INFO: "ci_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
861I, [2024-05-29T23:36:59.177094 #344] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
862I, [2024-05-29T23:37:21.451359 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
863INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
864INFO: analyzing "public.ci_pipeline_variables"
865INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
866I, [2024-05-29T23:37:23.076937 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
867I, [2024-05-29T23:37:23.078260 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
868I, [2024-05-29T23:37:23.079121 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
869INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
870INFO: analyzing "public.ci_pipeline_variables"
871INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
872INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
873INFO: analyzing "public.ci_job_artifacts"
874INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
875I, [2024-05-29T23:37:30.363955 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
876I, [2024-05-29T23:37:30.365008 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
877I, [2024-05-29T23:37:30.365801 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
878INFO: analyzing "public.p_ci_stages" inheritance tree
879INFO: analyzing "public.ci_stages"
880INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
881I, [2024-05-29T23:37:33.618802 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
882I, [2024-05-29T23:37:33.619797 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
883I, [2024-05-29T23:37:33.620565 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
884I, [2024-05-29T23:37:34.910131 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
885I, [2024-05-29T23:37:41.543744 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
886# [RSpecRunTime] Finishing example group spec/migrations/20230814144045_swap_timelogs_note_id_to_bigint_for_self_hosts_spec.rb. It took 5 minutes 2.79 seconds. Expected to take 3 minutes 25.41 seconds.
887# [RSpecRunTime] RSpec elapsed time: 5 minutes 8.44 seconds. Current RSS: ~1081M. Threads: 2. load average: 0.91 0.96 0.94 1/288 396
888.
889# [RSpecRunTime] Starting example group spec/migrations/cleanup_conversion_big_int_ci_build_needs_self_managed_spec.rb. Expected to take 3 minutes 17.89 seconds.
890CleanupConversionBigIntCiBuildNeedsSelfManaged
891 #up
892 when it is GitLab.com, dev, or test but not JiHu
893 does nothing
894# [RSpecRunTime] RSpec elapsed time: 7 minutes 0.08 second. Current RSS: ~1121M. Threads: 2. load average: 1.00 0.99 0.95 1/290 397
895.
896 when there is a self-managed instance with the temporary column already dropped
897main: == [advisory_lock_connection] object_id: 52492580, pg_backend_pid: 177
898main: == 20230724123547 CleanupConversionBigIntCiBuildNeedsSelfManaged: migrating ===
899main: -- column_exists?(:ci_build_needs, :id_convert_to_bigint)
900main: -> 0.0033s
901main: == 20230724123547 CleanupConversionBigIntCiBuildNeedsSelfManaged: migrated (0.0111s)
902main: == [advisory_lock_connection] object_id: 52492580, pg_backend_pid: 177
903 does nothing
904# [RSpecRunTime] RSpec elapsed time: 7 minutes 22.48 seconds. Current RSS: ~1136M. Threads: 2. load average: 1.00 0.99 0.96 1/290 398
905.
906 when there is a self-managed instance with the temporary columns
907 drops the temporary column
908# [RSpecRunTime] RSpec elapsed time: 8 minutes 4.56 seconds. Current RSS: ~1124M. Threads: 2. load average: 1.08 1.01 0.97 1/290 399
909.
910INFO: analyzing "public.p_ci_runner_machine_builds" inheritance tree
911INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_100"
912INFO: "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
913INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_101"
914INFO: "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
915INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_102"
916INFO: "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
917INFO: analyzing "public.p_ci_job_annotations" inheritance tree
918INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_100"
919INFO: "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
920INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_101"
921INFO: "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
922INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_102"
923INFO: "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
924INFO: analyzing "public.p_ci_builds_metadata" inheritance tree
925INFO: analyzing "public.ci_builds_metadata"
926INFO: "ci_builds_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
927INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_101"
928INFO: "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
929INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_102"
930INFO: "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
931INFO: analyzing "public.p_ci_builds" inheritance tree
932INFO: analyzing "public.ci_builds"
933INFO: "ci_builds": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
934INFO: analyzing "gitlab_partitions_dynamic.ci_builds_101"
935INFO: "ci_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
936INFO: analyzing "gitlab_partitions_dynamic.ci_builds_102"
937INFO: "ci_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
938I, [2024-05-29T23:41:18.575529 #344] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
939I, [2024-05-29T23:41:40.231852 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
940INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
941INFO: analyzing "public.ci_pipeline_variables"
942INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
943I, [2024-05-29T23:41:42.010392 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
944I, [2024-05-29T23:41:42.011543 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
945I, [2024-05-29T23:41:42.012266 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
946INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
947INFO: analyzing "public.ci_pipeline_variables"
948INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
949INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
950INFO: analyzing "public.ci_job_artifacts"
951INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
952I, [2024-05-29T23:41:48.440246 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
953I, [2024-05-29T23:41:48.441918 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
954I, [2024-05-29T23:41:48.442966 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
955INFO: analyzing "public.p_ci_stages" inheritance tree
956INFO: analyzing "public.ci_stages"
957INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
958I, [2024-05-29T23:41:51.934606 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
959I, [2024-05-29T23:41:51.936023 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
960I, [2024-05-29T23:41:51.936954 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
961I, [2024-05-29T23:41:53.163795 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
962I, [2024-05-29T23:41:59.829227 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
963# [RSpecRunTime] Finishing example group spec/migrations/cleanup_conversion_big_int_ci_build_needs_self_managed_spec.rb. It took 4 minutes 18.2 seconds. Expected to take 3 minutes 17.89 seconds.
964# [RSpecRunTime] RSpec elapsed time: 9 minutes 26.68 seconds. Current RSS: ~1108M. Threads: 2. load average: 0.95 1.00 0.97 2/291 400
965.
966# [RSpecRunTime] Starting example group spec/migrations/db/post_migrate/20231004091113_swap_columns_for_ci_sources_pipelines_pipeline_id_bigint_spec.rb. Expected to take 2 minutes 2.56 seconds.
967SwapColumnsForCiSourcesPipelinesPipelineIdBigint
968 when indexes are missing
969 behaves like swap conversion columns
970main: == [advisory_lock_connection] object_id: 86845900, pg_backend_pid: 199
971main: == 20231004091113 SwapColumnsForCiSourcesPipelinesPipelineIdBigint: migrating =
972main: -- index_exists?(:ci_sources_pipelines, :pipeline_id, {:name=>:index_ci_sources_pipelines_on_pipeline_id})
973main: -> 0.0135s
974main: -- view_exists?(:postgres_partitions)
975main: -> 0.0027s
976main: -- index_exists?(:ci_sources_pipelines, :pipeline_id, {:name=>:index_ci_sources_pipelines_on_pipeline_id, :algorithm=>:concurrently})
977main: -> 0.0097s
978main: -- add_index(:ci_sources_pipelines, :pipeline_id, {:name=>:index_ci_sources_pipelines_on_pipeline_id, :algorithm=>:concurrently})
979main: -> 0.0022s
980main: -- index_exists?(:ci_sources_pipelines, :source_pipeline_id, {:name=>:index_ci_sources_pipelines_on_source_pipeline_id})
981main: -> 0.0147s
982main: -- view_exists?(:postgres_partitions)
983main: -> 0.0024s
984main: -- index_exists?(:ci_sources_pipelines, :source_pipeline_id, {:name=>:index_ci_sources_pipelines_on_source_pipeline_id, :algorithm=>:concurrently})
985main: -> 0.0136s
986main: -- add_index(:ci_sources_pipelines, :source_pipeline_id, {:name=>:index_ci_sources_pipelines_on_source_pipeline_id, :algorithm=>:concurrently})
987main: -> 0.0022s
988main: -- execute("LOCK TABLE ci_pipelines, ci_sources_pipelines IN ACCESS EXCLUSIVE MODE")
989main: -> 0.0010s
990main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN pipeline_id TO temp_pipeline_id")
991main: -> 0.0011s
992main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN pipeline_id_convert_to_bigint TO pipeline_id")
993main: -> 0.0009s
994main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN temp_pipeline_id TO pipeline_id_convert_to_bigint")
995main: -> 0.0009s
996main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN source_pipeline_id TO temp_source_pipeline_id")
997main: -> 0.0010s
998main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN source_pipeline_id_convert_to_bigint TO source_pipeline_id")
999main: -> 0.0009s
1000main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN temp_source_pipeline_id TO source_pipeline_id_convert_to_bigint")
1001main: -> 0.0008s
1002main: -- quote_column_name(:trigger_68d7b6653c7d)
1003main: -> 0.0000s
1004main: -- execute("ALTER FUNCTION \"trigger_68d7b6653c7d\" RESET ALL")
1005main: -> 0.0008s
1006main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_e1bad85861 TO temp_fk_e1bad85861")
1007main: -> 0.0009s
1008main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_c1b5dc6b6f TO fk_e1bad85861")
1009main: -> 0.0011s
1010main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT temp_fk_e1bad85861 TO fk_c1b5dc6b6f")
1011main: -> 0.0009s
1012main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_d4e29af7d7 TO temp_fk_d4e29af7d7")
1013main: -> 0.0008s
1014main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_1df371767f TO fk_d4e29af7d7")
1015main: -> 0.0009s
1016main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT temp_fk_d4e29af7d7 TO fk_1df371767f")
1017main: -> 0.0008s
1018main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_pipeline_id RENAME TO temp_index_ci_sources_pipelines_on_pipeline_id")
1019main: -> 0.0008s
1020main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_pipeline_id_bigint RENAME TO index_ci_sources_pipelines_on_pipeline_id")
1021main: -> 0.0008s
1022main: -- execute("ALTER INDEX temp_index_ci_sources_pipelines_on_pipeline_id RENAME TO index_ci_sources_pipelines_on_pipeline_id_bigint")
1023main: -> 0.0008s
1024main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_source_pipeline_id RENAME TO temp_index_ci_sources_pipelines_on_source_pipeline_id")
1025main: -> 0.0009s
1026main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_source_pipeline_id_bigint RENAME TO index_ci_sources_pipelines_on_source_pipeline_id")
1027main: -> 0.0016s
1028main: -- execute("ALTER INDEX temp_index_ci_sources_pipelines_on_source_pipeline_id RENAME TO index_ci_sources_pipelines_on_source_pipeline_id_bigint")
1029main: -> 0.0015s
1030main: == 20231004091113 SwapColumnsForCiSourcesPipelinesPipelineIdBigint: migrated (0.1353s)
1031main: == [advisory_lock_connection] object_id: 86845900, pg_backend_pid: 199
1032 correctly swaps conversion columns
1033# [RSpecRunTime] RSpec elapsed time: 10 minutes 54.99 seconds. Current RSS: ~1158M. Threads: 2. load average: 0.87 0.95 0.96 1/290 401
1034.
1035 behaves like swap conversion columns
1036main: == [advisory_lock_connection] object_id: 87849480, pg_backend_pid: 204
1037main: == 20231004091113 SwapColumnsForCiSourcesPipelinesPipelineIdBigint: migrating =
1038main: -- index_exists?(:ci_sources_pipelines, :pipeline_id, {:name=>:index_ci_sources_pipelines_on_pipeline_id})
1039main: -> 0.0119s
1040main: -- index_exists?(:ci_sources_pipelines, :source_pipeline_id, {:name=>:index_ci_sources_pipelines_on_source_pipeline_id})
1041main: -> 0.0159s
1042main: -- execute("LOCK TABLE ci_pipelines, ci_sources_pipelines IN ACCESS EXCLUSIVE MODE")
1043main: -> 0.0013s
1044main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN pipeline_id TO temp_pipeline_id")
1045main: -> 0.0010s
1046main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN pipeline_id_convert_to_bigint TO pipeline_id")
1047main: -> 0.0010s
1048main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN temp_pipeline_id TO pipeline_id_convert_to_bigint")
1049main: -> 0.0010s
1050main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN source_pipeline_id TO temp_source_pipeline_id")
1051main: -> 0.0009s
1052main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN source_pipeline_id_convert_to_bigint TO source_pipeline_id")
1053main: -> 0.0009s
1054main: -- execute("ALTER TABLE ci_sources_pipelines RENAME COLUMN temp_source_pipeline_id TO source_pipeline_id_convert_to_bigint")
1055main: -> 0.0010s
1056main: -- quote_column_name(:trigger_68d7b6653c7d)
1057main: -> 0.0000s
1058main: -- execute("ALTER FUNCTION \"trigger_68d7b6653c7d\" RESET ALL")
1059main: -> 0.0009s
1060main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_e1bad85861 TO temp_fk_e1bad85861")
1061main: -> 0.0010s
1062main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_c1b5dc6b6f TO fk_e1bad85861")
1063main: -> 0.0010s
1064main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT temp_fk_e1bad85861 TO fk_c1b5dc6b6f")
1065main: -> 0.0011s
1066main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_d4e29af7d7 TO temp_fk_d4e29af7d7")
1067main: -> 0.0011s
1068main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT fk_1df371767f TO fk_d4e29af7d7")
1069main: -> 0.0010s
1070main: -- execute("ALTER TABLE ci_sources_pipelines RENAME CONSTRAINT temp_fk_d4e29af7d7 TO fk_1df371767f")
1071main: -> 0.0010s
1072main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_pipeline_id RENAME TO temp_index_ci_sources_pipelines_on_pipeline_id")
1073main: -> 0.0010s
1074main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_pipeline_id_bigint RENAME TO index_ci_sources_pipelines_on_pipeline_id")
1075main: -> 0.0009s
1076main: -- execute("ALTER INDEX temp_index_ci_sources_pipelines_on_pipeline_id RENAME TO index_ci_sources_pipelines_on_pipeline_id_bigint")
1077main: -> 0.0009s
1078main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_source_pipeline_id RENAME TO temp_index_ci_sources_pipelines_on_source_pipeline_id")
1079main: -> 0.0009s
1080main: -- execute("ALTER INDEX index_ci_sources_pipelines_on_source_pipeline_id_bigint RENAME TO index_ci_sources_pipelines_on_source_pipeline_id")
1081main: -> 0.0010s
1082main: -- execute("ALTER INDEX temp_index_ci_sources_pipelines_on_source_pipeline_id RENAME TO index_ci_sources_pipelines_on_source_pipeline_id_bigint")
1083main: -> 0.0012s
1084main: == 20231004091113 SwapColumnsForCiSourcesPipelinesPipelineIdBigint: migrated (0.0638s)
1085main: == [advisory_lock_connection] object_id: 87849480, pg_backend_pid: 204
1086 correctly swaps conversion columns
1087# [RSpecRunTime] RSpec elapsed time: 11 minutes 29.84 seconds. Current RSS: ~1137M. Threads: 2. load average: 0.91 0.95 0.96 2/290 402
1088.
1089I, [2024-05-29T23:44:44.995615 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
1090INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1091INFO: analyzing "public.ci_pipeline_variables"
1092INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1093I, [2024-05-29T23:44:46.834713 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
1094I, [2024-05-29T23:44:46.835853 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1095I, [2024-05-29T23:44:46.836589 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1096INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1097INFO: analyzing "public.ci_pipeline_variables"
1098INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1099INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
1100INFO: analyzing "public.ci_job_artifacts"
1101INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1102I, [2024-05-29T23:44:53.797534 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
1103I, [2024-05-29T23:44:53.798532 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1104I, [2024-05-29T23:44:53.799266 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1105INFO: analyzing "public.p_ci_stages" inheritance tree
1106INFO: analyzing "public.ci_stages"
1107INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1108I, [2024-05-29T23:44:57.629040 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1109I, [2024-05-29T23:44:57.630531 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1110I, [2024-05-29T23:44:57.631414 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1111I, [2024-05-29T23:44:59.032018 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1112I, [2024-05-29T23:45:06.348219 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1113# [RSpecRunTime] Finishing example group spec/migrations/db/post_migrate/20231004091113_swap_columns_for_ci_sources_pipelines_pipeline_id_bigint_spec.rb. It took 3 minutes 7.24 seconds. Expected to take 2 minutes 2.56 seconds.
1114# [RSpecRunTime] RSpec elapsed time: 12 minutes 33.96 seconds. Current RSS: ~1112M. Threads: 2. load average: 1.03 0.98 0.97 1/289 403
1115.
1116# [RSpecRunTime] Starting example group spec/migrations/20230821081603_queue_convert_credit_card_validation_data_to_hashes_spec.rb. Expected to take 1 minute 47.65 seconds.
1117QueueConvertCreditCardValidationDataToHashes
1118main: == [advisory_lock_connection] object_id: 119856300, pg_backend_pid: 222
1119main: == 20230821081603 QueueConvertCreditCardValidationDataToHashes: migrating =====
1120main: == 20230821081603 QueueConvertCreditCardValidationDataToHashes: migrated (0.0635s)
1121main: == [advisory_lock_connection] object_id: 119856300, pg_backend_pid: 222
1122 schedules a new batched migration
1123INFO: analyzing "public.p_ci_runner_machine_builds" inheritance tree
1124INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_100"
1125INFO: "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
1126INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_101"
1127INFO: "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
1128INFO: analyzing "gitlab_partitions_dynamic.ci_runner_machine_builds_102"
1129INFO: "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
1130INFO: analyzing "public.p_ci_job_annotations" inheritance tree
1131INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_100"
1132INFO: "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
1133INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_101"
1134INFO: "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
1135INFO: analyzing "gitlab_partitions_dynamic.ci_job_annotations_102"
1136INFO: "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
1137INFO: analyzing "public.p_ci_builds_metadata" inheritance tree
1138INFO: analyzing "public.ci_builds_metadata"
1139INFO: "ci_builds_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1140INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_101"
1141INFO: "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
1142INFO: analyzing "gitlab_partitions_dynamic.ci_builds_metadata_102"
1143INFO: "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
1144INFO: analyzing "public.p_ci_builds" inheritance tree
1145INFO: analyzing "public.ci_builds"
1146INFO: "ci_builds": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1147INFO: analyzing "gitlab_partitions_dynamic.ci_builds_101"
1148INFO: "ci_builds_101": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1149INFO: analyzing "gitlab_partitions_dynamic.ci_builds_102"
1150INFO: "ci_builds_102": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1151I, [2024-05-29T23:47:12.751853 #344] INFO -- : Database: 'main', Table: 'p_ci_finished_build_ch_sync_events': Lock Writes
1152I, [2024-05-29T23:47:34.602716 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
1153INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1154INFO: analyzing "public.ci_pipeline_variables"
1155INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1156I, [2024-05-29T23:47:36.506659 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
1157I, [2024-05-29T23:47:36.507788 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1158I, [2024-05-29T23:47:36.508541 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1159INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1160INFO: analyzing "public.ci_pipeline_variables"
1161INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1162INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
1163INFO: analyzing "public.ci_job_artifacts"
1164INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1165I, [2024-05-29T23:47:43.222158 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
1166I, [2024-05-29T23:47:43.223299 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1167I, [2024-05-29T23:47:43.224124 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1168INFO: analyzing "public.p_ci_stages" inheritance tree
1169INFO: analyzing "public.ci_stages"
1170INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1171I, [2024-05-29T23:47:46.860418 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1172I, [2024-05-29T23:47:46.861603 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1173I, [2024-05-29T23:47:46.862456 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1174I, [2024-05-29T23:47:48.205901 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1175I, [2024-05-29T23:47:55.074645 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1176# [RSpecRunTime] Finishing example group spec/migrations/20230821081603_queue_convert_credit_card_validation_data_to_hashes_spec.rb. It took 2 minutes 48.41 seconds. Expected to take 1 minute 47.65 seconds.
1177# [RSpecRunTime] RSpec elapsed time: 15 minutes 22.41 seconds. Current RSS: ~1117M. Threads: 2. load average: 0.93 0.97 0.98 1/289 404
1178.
1179# [RSpecRunTime] Starting example group spec/migrations/20231003142706_lower_project_build_timeout_to_respect_max_validation_spec.rb. Expected to take 1 minute 42.22 seconds.
1180LowerProjectBuildTimeoutToRespectMaxValidation
1181 #up
1182main: == [advisory_lock_connection] object_id: 152150100, pg_backend_pid: 240
1183main: == 20231003142706 LowerProjectBuildTimeoutToRespectMaxValidation: migrating ===
1184main: == 20231003142706 LowerProjectBuildTimeoutToRespectMaxValidation: migrated (0.0449s)
1185main: == [advisory_lock_connection] object_id: 152150100, pg_backend_pid: 240
1186 updates the build timeout
1187# [RSpecRunTime] RSpec elapsed time: 16 minutes 35.83 seconds. Current RSS: ~1146M. Threads: 2. load average: 0.94 0.96 0.98 1/289 405
1188.
1189 #down
1190main: == [advisory_lock_connection] object_id: 152998900, pg_backend_pid: 243
1191main: == 20231003142706 LowerProjectBuildTimeoutToRespectMaxValidation: migrating ===
1192main: == 20231003142706 LowerProjectBuildTimeoutToRespectMaxValidation: migrated (0.0421s)
1193main: == [advisory_lock_connection] object_id: 152998900, pg_backend_pid: 243
1194 does nothing
1195# [RSpecRunTime] RSpec elapsed time: 17 minutes 9.48 seconds. Current RSS: ~1160M. Threads: 2. load average: 0.97 0.97 0.98 1/289 406
1196.
1197I, [2024-05-29T23:50:24.960165 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
1198INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1199INFO: analyzing "public.ci_pipeline_variables"
1200INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1201I, [2024-05-29T23:50:26.971541 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
1202I, [2024-05-29T23:50:26.972586 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1203I, [2024-05-29T23:50:26.973281 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1204INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1205INFO: analyzing "public.ci_pipeline_variables"
1206INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1207INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
1208INFO: analyzing "public.ci_job_artifacts"
1209INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1210I, [2024-05-29T23:50:34.013262 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
1211I, [2024-05-29T23:50:34.014335 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1212I, [2024-05-29T23:50:34.015131 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1213INFO: analyzing "public.p_ci_stages" inheritance tree
1214INFO: analyzing "public.ci_stages"
1215INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1216I, [2024-05-29T23:50:37.851037 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1217I, [2024-05-29T23:50:37.852327 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1218I, [2024-05-29T23:50:37.853207 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1219I, [2024-05-29T23:50:39.210412 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1220I, [2024-05-29T23:50:46.245712 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1221# [RSpecRunTime] Finishing example group spec/migrations/20231003142706_lower_project_build_timeout_to_respect_max_validation_spec.rb. It took 2 minutes 51.42 seconds. Expected to take 1 minute 42.22 seconds.
1222# [RSpecRunTime] RSpec elapsed time: 18 minutes 13.86 seconds. Current RSS: ~1117M. Threads: 2. load average: 0.99 0.98 0.99 1/289 407
1223.
1224# [RSpecRunTime] Starting example group spec/migrations/20231016194927_queue_delete_invalid_protected_branch_push_access_levels_spec.rb. Expected to take 1 minute 31.46 seconds.
1225QueueDeleteInvalidProtectedBranchPushAccessLevels
1226main: == [advisory_lock_connection] object_id: 183688840, pg_backend_pid: 261
1227main: == 20231016194927 QueueDeleteInvalidProtectedBranchPushAccessLevels: migrating
1228main: == 20231016194927 QueueDeleteInvalidProtectedBranchPushAccessLevels: migrated (0.0724s)
1229main: == [advisory_lock_connection] object_id: 183688840, pg_backend_pid: 261
1230 schedules a new batched migration
1231I, [2024-05-29T23:52:53.071916 #344] INFO -- : Database: 'main', Table: 'ci_job_token_group_scope_links': Lock Writes
1232INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1233INFO: analyzing "public.ci_pipeline_variables"
1234INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1235I, [2024-05-29T23:52:55.003352 #344] INFO -- : Database: 'main', Table: 'p_ci_pipeline_variables': Lock Writes
1236I, [2024-05-29T23:52:55.004755 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1237I, [2024-05-29T23:52:55.005617 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1238INFO: analyzing "public.p_ci_pipeline_variables" inheritance tree
1239INFO: analyzing "public.ci_pipeline_variables"
1240INFO: "ci_pipeline_variables": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1241INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
1242INFO: analyzing "public.ci_job_artifacts"
1243INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1244I, [2024-05-29T23:53:02.000150 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
1245I, [2024-05-29T23:53:02.001347 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1246I, [2024-05-29T23:53:02.002169 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1247INFO: analyzing "public.p_ci_stages" inheritance tree
1248INFO: analyzing "public.ci_stages"
1249INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1250I, [2024-05-29T23:53:05.788655 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1251I, [2024-05-29T23:53:05.789904 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1252I, [2024-05-29T23:53:05.790703 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1253I, [2024-05-29T23:53:07.100276 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1254I, [2024-05-29T23:53:14.230313 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1255# [RSpecRunTime] Finishing example group spec/migrations/20231016194927_queue_delete_invalid_protected_branch_push_access_levels_spec.rb. It took 2 minutes 27.8 seconds. Expected to take 1 minute 31.46 seconds.
1256# [RSpecRunTime] RSpec elapsed time: 20 minutes 41.7 seconds. Current RSS: ~1115M. Threads: 2. load average: 1.06 1.01 1.00 1/289 408
1257.
1258# [RSpecRunTime] Starting example group spec/migrations/20240222214106_set_default_organization_visibility_to_public_spec.rb. Expected to take 1 minute 19.98 seconds.
1259SetDefaultOrganizationVisibilityToPublic
1260 #down
1261 when default organization exists
1262main: == [advisory_lock_connection] object_id: 209373880, pg_backend_pid: 276
1263main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrating =========
1264main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrated (0.0169s)
1265main: == [advisory_lock_connection] object_id: 209373880, pg_backend_pid: 276
1266 updates only the default organization visibility_level to private
1267# [RSpecRunTime] RSpec elapsed time: 21 minutes 25.15 seconds. Current RSS: ~1151M. Threads: 2. load average: 1.03 1.01 1.00 1/289 409
1268.
1269 when default organization does not exist
1270 does not error
1271# [RSpecRunTime] RSpec elapsed time: 21 minutes 38.89 seconds. Current RSS: ~1139M. Threads: 2. load average: 1.02 1.01 1.00 1/289 410
1272.
1273 #up
1274 when default organization exists
1275main: == [advisory_lock_connection] object_id: 210780300, pg_backend_pid: 283
1276main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrating =========
1277main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrated (0.0169s)
1278main: == [advisory_lock_connection] object_id: 210780300, pg_backend_pid: 283
1279 updates only the default organization visibility_level to public
1280# [RSpecRunTime] RSpec elapsed time: 21 minutes 47.56 seconds. Current RSS: ~1120M. Threads: 2. load average: 1.02 1.01 1.00 1/289 411
1281.
1282 when default organization does not exist
1283main: == [advisory_lock_connection] object_id: 211384200, pg_backend_pid: 285
1284main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrating =========
1285main: == 20240222214106 SetDefaultOrganizationVisibilityToPublic: migrated (0.0128s)
1286main: == [advisory_lock_connection] object_id: 211384200, pg_backend_pid: 285
1287 does not error
1288# [RSpecRunTime] RSpec elapsed time: 21 minutes 56.23 seconds. Current RSS: ~1121M. Threads: 2. load average: 1.02 1.01 1.00 1/288 412
1289.
1290I, [2024-05-29T23:54:54.541960 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1291I, [2024-05-29T23:55:01.913198 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1292# [RSpecRunTime] Finishing example group spec/migrations/20240222214106_set_default_organization_visibility_to_public_spec.rb. It took 1 minute 48.52 seconds. Expected to take 1 minute 19.98 seconds.
1293# [RSpecRunTime] RSpec elapsed time: 22 minutes 30.25 seconds. Current RSS: ~1126M. Threads: 2. load average: 0.90 0.97 0.99 1/288 413
1294.
1295# [RSpecRunTime] Starting example group spec/migrations/update_pipeline_triggers_plan_limits_spec.rb. Expected to take 1 minute 1.96 seconds.
1296UpdatePipelineTriggersPlanLimits
1297 when on gitlab.com
1298main: == [advisory_lock_connection] object_id: 230903440, pg_backend_pid: 298
1299main: == 20240226191235 UpdatePipelineTriggersPlanLimits: migrating =================
1300main: -- quote_column_name("pipeline_triggers")
1301main: -> 0.0000s
1302main: -- quote("premium_trial")
1303main: -> 0.0000s
1304main: -- quote(25000)
1305main: -> 0.0000s
1306main: -- execute("INSERT INTO plan_limits (plan_id, \"pipeline_triggers\")\nSELECT id, '25000' FROM plans WHERE name = 'premium_trial' LIMIT 1\nON CONFLICT (plan_id) DO UPDATE SET \"pipeline_triggers\" = EXCLUDED.\"pipeline_triggers\";\n")
1307main: -> 0.0031s
1308main: -- quote_column_name("pipeline_triggers")
1309main: -> 0.0000s
1310main: -- quote("ultimate_trial")
1311main: -> 0.0000s
1312main: -- quote(25000)
1313main: -> 0.0000s
1314main: -- execute("INSERT INTO plan_limits (plan_id, \"pipeline_triggers\")\nSELECT id, '25000' FROM plans WHERE name = 'ultimate_trial' LIMIT 1\nON CONFLICT (plan_id) DO UPDATE SET \"pipeline_triggers\" = EXCLUDED.\"pipeline_triggers\";\n")
1315main: -> 0.0024s
1316main: -- quote_column_name("pipeline_triggers")
1317main: -> 0.0000s
1318main: -- quote("opensource")
1319main: -> 0.0000s
1320main: -- quote(25000)
1321main: -> 0.0000s
1322main: -- execute("INSERT INTO plan_limits (plan_id, \"pipeline_triggers\")\nSELECT id, '25000' FROM plans WHERE name = 'opensource' LIMIT 1\nON CONFLICT (plan_id) DO UPDATE SET \"pipeline_triggers\" = EXCLUDED.\"pipeline_triggers\";\n")
1323main: -> 0.0024s
1324main: == 20240226191235 UpdatePipelineTriggersPlanLimits: migrated (0.0191s) ========
1325main: == [advisory_lock_connection] object_id: 230903440, pg_backend_pid: 298
1326 correctly migrates up and down
1327# [RSpecRunTime] RSpec elapsed time: 23 minutes 20.13 seconds. Current RSS: ~1160M. Threads: 2. load average: 1.00 1.00 1.00 1/288 414
1328.
1329 when on self-managed
1330main: == [advisory_lock_connection] object_id: 231980760, pg_backend_pid: 302
1331main: == 20240226191235 UpdatePipelineTriggersPlanLimits: migrating =================
1332main: == 20240226191235 UpdatePipelineTriggersPlanLimits: migrated (0.0106s) ========
1333main: == [advisory_lock_connection] object_id: 231980760, pg_backend_pid: 302
1334 correctly migrates up and down
1335# [RSpecRunTime] RSpec elapsed time: 23 minutes 36.03 seconds. Current RSS: ~1162M. Threads: 2. load average: 1.00 1.00 1.00 1/288 415
1336.
1337INFO: analyzing "public.p_ci_job_artifacts" inheritance tree
1338INFO: analyzing "public.ci_job_artifacts"
1339INFO: "ci_job_artifacts": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1340I, [2024-05-29T23:56:33.895322 #344] INFO -- : Database: 'main', Table: 'p_ci_job_artifacts': Lock Writes
1341I, [2024-05-29T23:56:33.897054 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1342I, [2024-05-29T23:56:33.898110 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1343INFO: analyzing "public.p_ci_stages" inheritance tree
1344INFO: analyzing "public.ci_stages"
1345INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1346I, [2024-05-29T23:56:37.769606 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1347I, [2024-05-29T23:56:37.770742 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1348I, [2024-05-29T23:56:37.771540 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1349I, [2024-05-29T23:56:39.118054 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1350I, [2024-05-29T23:56:46.442315 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1351# [RSpecRunTime] Finishing example group spec/migrations/update_pipeline_triggers_plan_limits_spec.rb. It took 1 minute 44.18 seconds. Expected to take 1 minute 1.96 seconds.
1352# [RSpecRunTime] RSpec elapsed time: 24 minutes 14.47 seconds. Current RSS: ~1120M. Threads: 2. load average: 0.85 0.97 0.99 1/288 416
1353.
1354# [RSpecRunTime] Starting example group spec/migrations/20240213210124_queue_backfill_default_organization_users_spec.rb. Expected to take 47.26 seconds.
1355QueueBackfillDefaultOrganizationUsers
1356main: == [advisory_lock_connection] object_id: 252364180, pg_backend_pid: 316
1357main: == 20240213210124 QueueBackfillDefaultOrganizationUsers: migrating ============
1358main: == 20240213210124 QueueBackfillDefaultOrganizationUsers: migrated (0.0684s) ===
1359main: == [advisory_lock_connection] object_id: 252364180, pg_backend_pid: 316
1360 schedules a new batched migration
1361INFO: analyzing "public.p_ci_stages" inheritance tree
1362INFO: analyzing "public.ci_stages"
1363INFO: "ci_stages": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
1364I, [2024-05-29T23:57:59.433689 #344] INFO -- : Database: 'main', Table: 'p_ci_stages': Lock Writes
1365I, [2024-05-29T23:57:59.435521 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Lock timeout is set", :current_iteration=>1, :lock_timeout_in_ms=>100}
1366I, [2024-05-29T23:57:59.436808 #344] INFO -- : {:method=>"with_lock_retries", :class=>"gitlab:db:lock_writes", :message=>"Migration finished", :current_iteration=>1, :lock_timeout_in_ms=>100}
1367I, [2024-05-29T23:58:00.869955 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1368I, [2024-05-29T23:58:08.009971 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1369# [RSpecRunTime] Finishing example group spec/migrations/20240213210124_queue_backfill_default_organization_users_spec.rb. It took 1 minute 22.45 seconds. Expected to take 47.26 seconds.
1370# [RSpecRunTime] RSpec elapsed time: 25 minutes 36.95 seconds. Current RSS: ~1117M. Threads: 2. load average: 0.90 0.95 0.99 1/288 417
1371.
1372# [RSpecRunTime] Starting example group spec/migrations/migrate_custom_permissions_spec.rb. Expected to take 39.86 seconds.
1373MigrateCustomPermissions
1374 correctly migrates up and down
1375I, [2024-05-29T23:59:15.563090 #344] INFO -- : Database: 'main', Table: 'p_ci_build_names': Lock Writes
1376I, [2024-05-29T23:59:22.485229 #344] INFO -- : Database: 'main', Table: 'p_ci_builds_execution_configs': Lock Writes
1377# [RSpecRunTime] Finishing example group spec/migrations/migrate_custom_permissions_spec.rb. It took 1 minute 13.44 seconds. Expected to take 39.86 seconds.
1378# [RSpecRunTime] RSpec elapsed time: 26 minutes 50.44 seconds. Current RSS: ~1118M. Threads: 2. load average: 1.02 0.98 1.00 1/289 418
1379.
1380# [RSpecRunTime] Starting example group spec/migrations/20240502044605_remove_create_empty_embeddings_records_worker_spec.rb. Expected to take 18.23 seconds.
1381RemoveCreateEmptyEmbeddingsRecordsWorker
1382 when cron job exists
1383main: == [advisory_lock_connection] object_id: 283058780, pg_backend_pid: 343
1384main: == 20240502044605 RemoveCreateEmptyEmbeddingsRecordsWorker: migrating =========
1385main: == 20240502044605 RemoveCreateEmptyEmbeddingsRecordsWorker: migrated (0.0158s)
1386main: == [advisory_lock_connection] object_id: 283058780, pg_backend_pid: 343
1387 deletes the cron job and enqueued jobs
1388# [RSpecRunTime] RSpec elapsed time: 27 minutes 4.1 seconds. Current RSS: ~1123M. Threads: 2. load average: 0.94 0.96 0.99 1/289 419
1389.
1390 when cron job does not exist
1391main: == [advisory_lock_connection] object_id: 283825400, pg_backend_pid: 345
1392main: == 20240502044605 RemoveCreateEmptyEmbeddingsRecordsWorker: migrating =========
1393main: == 20240502044605 RemoveCreateEmptyEmbeddingsRecordsWorker: migrated (0.0105s)
1394main: == [advisory_lock_connection] object_id: 283825400, pg_backend_pid: 345
1395 no-ops
1396# [RSpecRunTime] RSpec elapsed time: 27 minutes 9.75 seconds. Current RSS: ~1114M. Threads: 2. load average: 1.03 0.98 1.00 1/289 420
1397.
1398# [RSpecRunTime] Finishing example group spec/migrations/20240502044605_remove_create_empty_embeddings_records_worker_spec.rb. It took 32.14 seconds. Expected to take 18.23 seconds.
1399# [RSpecRunTime] RSpec elapsed time: 27 minutes 22.61 seconds. Current RSS: ~1100M. Threads: 2. load average: 0.94 0.96 0.99 1/289 421
1400.
1401# [RSpecRunTime] Starting example group spec/migrations/increase_quantity_for_gitlabcom_duo_pro_trials_spec.rb. Expected to take 11.53 seconds.
1402IncreaseQuantityForGitlabcomDuoProTrials
1403 #up
1404main: == [advisory_lock_connection] object_id: 285780980, pg_backend_pid: 355
1405main: == 20240510125400 IncreaseQuantityForGitlabcomDuoProTrials: migrating =========
1406main: -- exec_query("SELECT COUNT(*) AS count FROM \"subscription_add_on_purchases\" WHERE \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30'")
1407main: -> 0.0031s
1408main: -- exec_query("SELECT \"subscription_add_on_purchases\".\"id\" FROM \"subscription_add_on_purchases\" WHERE \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30' ORDER BY \"subscription_add_on_purchases\".\"id\" ASC LIMIT 1")
1409main: -> 0.0019s
1410main: -- exec_query("SELECT \"subscription_add_on_purchases\".\"id\" FROM \"subscription_add_on_purchases\" WHERE \"subscription_add_on_purchases\".\"id\" >= 2 AND \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30' ORDER BY \"subscription_add_on_purchases\".\"id\" ASC LIMIT 1 OFFSET 1")
1411main: -> 0.0030s
1412main: -- transaction(nil)
1413main: -- execute("UPDATE \"subscription_add_on_purchases\" SET \"quantity\" = 100 WHERE \"subscription_add_on_purchases\".\"id\" >= 2 AND \"subscription_add_on_purchases\".\"id\" < 3 AND \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30'")
1414main: -> 0.0036s
1415main: -> 0.0057s
1416main: -- exec_query("SELECT \"subscription_add_on_purchases\".\"id\" FROM \"subscription_add_on_purchases\" WHERE \"subscription_add_on_purchases\".\"id\" >= 3 AND \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30' ORDER BY \"subscription_add_on_purchases\".\"id\" ASC LIMIT 1 OFFSET 1")
1417main: -> 0.0024s
1418main: -- transaction(nil)
1419main: -- execute("UPDATE \"subscription_add_on_purchases\" SET \"quantity\" = 100 WHERE \"subscription_add_on_purchases\".\"id\" >= 3 AND \"subscription_add_on_purchases\".\"subscription_add_on_id\" = 1 AND \"subscription_add_on_purchases\".\"trial\" = TRUE AND \"subscription_add_on_purchases\".\"expires_on\" >= '2024-05-30'")
1420main: -> 0.0028s
1421main: -> 0.0040s
1422main: == 20240510125400 IncreaseQuantityForGitlabcomDuoProTrials: migrated (0.0569s)
1423main: == [advisory_lock_connection] object_id: 285780980, pg_backend_pid: 355
1424 update only the active duo_pro trials quantity to 100
1425# [RSpecRunTime] RSpec elapsed time: 27 minutes 34.12 seconds. Current RSS: ~1115M. Threads: 2. load average: 0.88 0.95 0.99 1/289 422
1426.
1427# [RSpecRunTime] Finishing example group spec/migrations/increase_quantity_for_gitlabcom_duo_pro_trials_spec.rb. It took 23.28 seconds. Expected to take 11.53 seconds.
1428# [RSpecRunTime] RSpec elapsed time: 27 minutes 45.93 seconds. Current RSS: ~1104M. Threads: 2. load average: 0.90 0.95 0.99 1/289 423
1429.
1430auto_explain log contains 942 entries for main, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-migration-pg14-13-15.344.main.ndjson.gz
1431took 22.626379173
1432auto_explain log contains 943 entries for ci, writing to /builds/gitlab-org/gitlab/auto_explain/rspec-migration-pg14-13-15.344.ci.ndjson.gz
1433took 22.628974983
1434[TEST PROF INFO] EventProf results for sql.active_record
1435Total time: 14:10.644 of 27:40.297 (51.23%)
1436Total events: 617475
1437Top 5 slowest suites (by time):
1438CleanupConver...edsSelfManaged (./spec/migrations/cleanup_conversion_big_int_ci_build_needs_self_managed_spec.rb:6) – 01:59.467 (79359 / 3) of 04:18.233 (46.26%)
1439SwapTimelogsN...ntForSelfHosts (./spec/migrations/20230814144045_swap_timelogs_note_id_to_bigint_for_self_hosts_spec.rb:6) – 01:57.608 (77555 / 4) of 05:02.821 (38.84%)
1440QueueConvertC...onDataToHashes (./spec/migrations/20230821081603_queue_convert_credit_card_validation_data_to_hashes_spec.rb:6) – 01:39.202 (70343 / 1) of 02:48.446 (58.89%)
1441LowerProjectB...tMaxValidation (./spec/migrations/20231003142706_lower_project_build_timeout_to_respect_max_validation_spec.rb:6) – 01:32.430 (67050 / 2) of 02:51.459 (53.91%)
1442SwapColumnsFo...pelineIdBigint (./spec/migrations/db/post_migrate/20231004091113_swap_columns_for_ci_sources_pipelines_pipeline_id_bigint_spec.rb:6) – 01:31.760 (67070 / 2) of 03:07.278 (49.0%)
1443Knapsack report was generated. Preview:
1444{
1445 "spec/migrations/20230814144045_swap_timelogs_note_id_to_bigint_for_self_hosts_spec.rb": 232.31455916599998,
1446 "spec/migrations/cleanup_conversion_big_int_ci_build_needs_self_managed_spec.rb": 176.25716781100027,
1447 "spec/migrations/db/post_migrate/20231004091113_swap_columns_for_ci_sources_pipelines_pipeline_id_bigint_spec.rb": 123.29057332000002,
1448 "spec/migrations/20230821081603_queue_convert_credit_card_validation_data_to_hashes_spec.rb": 98.4398430250003,
1449 "spec/migrations/20231003142706_lower_project_build_timeout_to_respect_max_validation_spec.rb": 107.2022039500007,
1450 "spec/migrations/20231016194927_queue_delete_invalid_protected_branch_push_access_levels_spec.rb": 85.77019681099955,
1451 "spec/migrations/20240222214106_set_default_organization_visibility_to_public_spec.rb": 74.66074875100003,
1452 "spec/migrations/update_pipeline_triggers_plan_limits_spec.rb": 65.90958432099978,
1453 "spec/migrations/20240213210124_queue_backfill_default_organization_users_spec.rb": 46.821759841999665,
1454 "spec/migrations/migrate_custom_permissions_spec.rb": 41.355625551999765,
1455 "spec/migrations/20240502044605_remove_create_empty_embeddings_records_worker_spec.rb": 19.48247602399988,
1456 "spec/migrations/increase_quantity_for_gitlabcom_duo_pro_trials_spec.rb": 11.626907251000375
1457}
1458Knapsack global time execution for tests: 18m 03s
1459Finished in 28 minutes 31 seconds (files took 1 minute 1.33 seconds to load)
146024 examples, 0 failures
1461Randomized with seed 2050
1462[TEST PROF INFO] Time spent in factories: 00:00.245 (0.01% of total time)
1463RSpec exited with 0.
1464No examples to retry, congrats!
1465 Running after_script 00:05
1466Running after script...
1467$ source scripts/utils.sh
1468$ bundle exec gem list gitlab_quality-test_tooling
1469gitlab_quality-test_tooling (1.26.0)
1470$ section_start "failed-test-issues" "Report test failures" # collapsed multi-line command
1471 Report test failures 00:00
1473$ section_start "flaky-test-issues" "Report test flakiness" # collapsed multi-line command
1474 Report test flakiness 00:00
1476$ section_start "slow-test-issues" "Report test slowness" # collapsed multi-line command
1477 Report test slowness 00:00
1479$ section_start "slow-test-merge-request-report-note" "Report test slowness in MR note" # collapsed multi-line command
1480 Report test slowness in MR note 00:02
1483$ section_start "knapsack-report-issues" "Report test files close to timing out" # collapsed multi-line command
1484 Report test files close to timing out 00:01
1487$ tooling/bin/push_job_metrics || true
1488[job-metrics] Pushing job metrics file for the CI/CD job.
1489[job-metrics] Pushed 4 CI job metric entries to InfluxDB.
1490 Saving cache for successful job 00:01
1491Not uploading cache ruby-gems-debian-bookworm-ruby-3.2-17 due to policy
1492 Uploading artifacts for successful job 00:05
1493Uploading artifacts...
1494auto_explain/: found 3 matching artifact files and directories
1495coverage/: found 5 matching artifact files and directories
1496crystalball/: found 2 matching artifact files and directories
1497WARNING: deprecations/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
1498knapsack/: found 4 matching artifact files and directories
1499rspec/: found 16 matching artifact files and directories
1500WARNING: tmp/capybara/: no matching files. Ensure that the artifact path is relative to the working directory (/builds/gitlab-org/gitlab)
1501log/*.log: found 13 matching artifact files and directories
1502WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/6975007391/artifacts?artifact_format=zip&artifact_type=archive&expire_in=31d new-url=https://gitlab.com
1503WARNING: Retrying... context=artifacts-uploader error=request redirected
1504Uploading artifacts as "archive" to coordinator... 201 Created id=6975007391 responseStatus=201 Created token=glcbt-65
1505Uploading artifacts...
1506rspec/rspec-*.xml: found 1 matching artifact files and directories
1507WARNING: Upload request redirected location=https://gitlab.com/api/v4/jobs/6975007391/artifacts?artifact_format=gzip&artifact_type=junit&expire_in=31d new-url=https://gitlab.com
1508WARNING: Retrying... context=artifacts-uploader error=request redirected
1509Uploading artifacts as "junit" to coordinator... 201 Created id=6975007391 responseStatus=201 Created token=glcbt-65
1510 Cleaning up project directory and file based variables 00:00
1511Job succeeded