Spec failures in Ruby 2.7.7: expected `Gitlab::Memory::Instrumentation.available?` to be truthy, got false

Summary

This failure is impacting the following tests:

  • rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:13 # Gitlab::Memory::Instrumentation.available? returns true
  • rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:21 # Gitlab::Memory::Instrumentation.start_thread_memory_allocations a hash is returned
  • rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:50 # Gitlab::Memory::Instrumentation.with_memory_allocations a hash is returned
Failures:
  1) Gitlab::Memory::Instrumentation.available? returns true
    Failure/Error: expect(described_class).to be_available
      expected `Gitlab::Memory::Instrumentation.available?` to be truthy, got false
    # ./spec/lib/gitlab/memory/instrumentation_spec.rb:14:in `block (3 levels) in <main>'
    # ./spec/spec_helper.rb:413:in `block (3 levels) in <top (required)>'
    # ./spec/support/sidekiq_middleware.rb:18:in `with_sidekiq_server_middleware'
    # ./spec/spec_helper.rb:405:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:401:in `block (3 levels) in <top (required)>'
    # ./lib/gitlab/application_context.rb:59:in `with_raw_context'
    # ./spec/spec_helper.rb:401:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:241:in `block (2 levels) in <top (required)>'
    # ./spec/support/system_exit_detected.rb:7:in `block (2 levels) in <main>'
    # ./spec/support/flaky_tests.rb:27:in `block (2 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (3 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:60:in `with_cross_joins_prevented'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (2 levels) in <main>'
  2) Gitlab::Memory::Instrumentation.start_thread_memory_allocations a hash is returned
    Failure/Error: is_expected.to be_a(Hash)
      expected nil to be a kind of Hash
    # ./spec/lib/gitlab/memory/instrumentation_spec.rb:22:in `block (3 levels) in <main>'
    # ./spec/spec_helper.rb:413:in `block (3 levels) in <top (required)>'
    # ./spec/support/sidekiq_middleware.rb:18:in `with_sidekiq_server_middleware'
    # ./spec/spec_helper.rb:405:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:401:in `block (3 levels) in <top (required)>'
    # ./lib/gitlab/application_context.rb:59:in `with_raw_context'
    # ./spec/spec_helper.rb:401:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:241:in `block (2 levels) in <top (required)>'
    # ./spec/support/system_exit_detected.rb:7:in `block (2 levels) in <main>'
    # ./spec/support/flaky_tests.rb:27:in `block (2 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (3 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:60:in `with_cross_joins_prevented'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (2 levels) in <main>'
  3) Gitlab::Memory::Instrumentation.with_memory_allocations a hash is returned
    Failure/Error: mem_total_bytes: eq(result[:mem_bytes] + 40 * result[:mem_objects])
    NoMethodError:
      undefined method `[]' for nil:NilClass
    # ./spec/lib/gitlab/memory/instrumentation_spec.rb:56:in `block (3 levels) in <main>'
    # ./spec/spec_helper.rb:413:in `block (3 levels) in <top (required)>'
    # ./spec/support/sidekiq_middleware.rb:18:in `with_sidekiq_server_middleware'
    # ./spec/spec_helper.rb:405:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:401:in `block (3 levels) in <top (required)>'
    # ./lib/gitlab/application_context.rb:59:in `with_raw_context'
    # ./spec/spec_helper.rb:401:in `block (2 levels) in <top (required)>'
    # ./spec/spec_helper.rb:241:in `block (2 levels) in <top (required)>'
    # ./spec/support/system_exit_detected.rb:7:in `block (2 levels) in <main>'
    # ./spec/support/flaky_tests.rb:27:in `block (2 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (3 levels) in <main>'
    # ./spec/support/database/prevent_cross_joins.rb:60:in `with_cross_joins_prevented'
    # ./spec/support/database/prevent_cross_joins.rb:106:in `block (2 levels) in <main>'
Finished in 3.18 seconds (files took 48.43 seconds to load)
3 examples, 3 failures
Failed examples:
rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:13 # Gitlab::Memory::Instrumentation.available? returns true
rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:21 # Gitlab::Memory::Instrumentation.start_thread_memory_allocations a hash is returned
rspec ./spec/lib/gitlab/memory/instrumentation_spec.rb:50 # Gitlab::Memory::Instrumentation.with_memory_allocations a hash is returned
  • rspec ./spec/initializers/lograge_spec.rb:99
Failures:
  1) lograge for Controller requests when logging memory allocations logs memory usage metrics
     Failure/Error: return @app.call(env) unless rendering_memory_profiler?(request)
       #<Lograge::Formatters::Json:0x00007fadc4872520> received :call with unexpected arguments
         expected: (a hash including :mem_objects)
              got: ({:action=>"index", :controller=>"RootController", "correlation_id"=>"new-correlation-id", :cpu_s=>0.0...uration_s=>5, :time=>"2022-11-29T18:39:19.737Z", :view_duration_s=>0.0, :worker_id=>"process_16418"})
       Diff:
       @@ -1,64 +1,127 @@
       -["a hash including :mem_objects"]
       +[{:action=>"index",
       +  :controller=>"RootController",
       +  "correlation_id"=>"new-correlation-id",
       +  :cpu_s=>0.019701,
       +  :db_cached_count=>0,
       +  :db_ci_cached_count=>0,
       +  :db_ci_count=>0,
       +  :db_ci_duration_s=>0.0,
       +  :db_ci_replica_cached_count=>0,
       +  :db_ci_replica_count=>0,
       +  :db_ci_replica_duration_s=>0.0,
       +  :db_ci_replica_wal_cached_count=>0,
       +  :db_ci_replica_wal_count=>0,
       +  :db_ci_wal_cached_count=>0,
       +  :db_ci_wal_count=>0,
       +  :db_count=>1,
       +  :db_duration_s=>0.0005,
       +  :db_geo_cached_count=>0,
       +  :db_geo_count=>0,
       +  :db_geo_duration_s=>0.0,
       +  :db_geo_wal_cached_count=>0,
       +  :db_geo_wal_count=>0,
       +  :db_main_cached_count=>0,
       +  :db_main_count=>1,
       +  :db_main_duration_s=>0.001,
       +  :db_main_replica_cached_count=>0,
       +  :db_main_replica_count=>0,
       +  :db_main_replica_duration_s=>0.0,
       +  :db_main_replica_wal_cached_count=>0,
       +  :db_main_replica_wal_count=>0,
       +  :db_main_wal_cached_count=>0,
       +  :db_main_wal_count=>0,
       +  :db_primary_cached_count=>0,
       +  :db_primary_count=>1,
       +  :db_primary_duration_s=>0.001,
       +  :db_primary_wal_cached_count=>0,
       +  :db_primary_wal_count=>0,
       +  :db_replica_cached_count=>0,
       +  :db_replica_count=>0,
       +  :db_replica_duration_s=>0.0,
       +  :db_replica_wal_cached_count=>0,
       +  :db_replica_wal_count=>0,
       +  :db_write_count=>0,
       +  :duration_s=>0.0117,
       +  :feature_flag_states=>[],
       +  :format=>:html,
       +  :location=>"http://www.example.com/users/sign_in",
       +  "meta.caller_id"=>"RootController#index",
       +  "meta.client_id"=>"ip/127.0.0.1",
       +  "meta.feature_category"=>"projects",
       +  "meta.remote_ip"=>"127.0.0.1",
       +  :method=>"GET",
       +  :params=>[],
       +  :path=>"/",
       +  :pid=>16418,
       +  :rate_limiting_gates=>[],
       +  :remote_ip=>"127.0.0.1",
       +  :request_urgency=>:low,
       +  :response_bytes=>102,
       +  :status=>302,
       +  :target_duration_s=>5,
       +  :time=>"2022-11-29T18:39:19.737Z",
       +  :view_duration_s=>0.0,
       +  :worker_id=>"process_16418"}]
     # ./lib/gitlab/middleware/memory_report.rb:13:in `call'
     # ./lib/gitlab/middleware/speedscope.rb:13:in `call'
     # ./lib/gitlab/query_limiting/middleware.rb:17:in `block in call'
     # ./lib/gitlab/query_limiting/transaction.rb:45:in `run'
     # ./lib/gitlab/query_limiting/middleware.rb:16:in `call'
     # ./lib/gitlab/database/load_balancing/rack_middleware.rb:23:in `call'
     # ./lib/gitlab/jira/middleware.rb:19:in `call'
     # ./lib/gitlab/middleware/go.rb:20:in `call'
     # ./lib/gitlab/etag_caching/middleware.rb:21:in `call'
     # ./lib/gitlab/middleware/query_analyzer.rb:11:in `block in call'
     # ./lib/gitlab/database/query_analyzer.rb:37:in `within'
     # ./lib/gitlab/middleware/query_analyzer.rb:11:in `call'
     # ./lib/gitlab/middleware/multipart.rb:173:in `call'
     # ./lib/gitlab/middleware/read_only/controller.rb:50:in `call'
     # ./lib/gitlab/middleware/read_only.rb:18:in `call'
     # ./lib/gitlab/middleware/same_site_cookies.rb:27:in `call'
     # ./lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'
     # ./lib/gitlab/middleware/basic_health_check.rb:25:in `call'
     # ./lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'
     # ./lib/gitlab/middleware/request_context.rb:21:in `call'
     # ./lib/gitlab/middleware/webhook_recursion_detection.rb:15:in `call'
     # ./config/initializers/fix_local_cache_middleware.rb:11:in `call'
     # ./lib/gitlab/middleware/compressed_json.rb:37:in `call'
     # ./lib/gitlab/middleware/static.rb:11:in `call'
     # ./lib/gitlab/testing/clear_process_memory_cache_middleware.rb:13:in `call'
     # ./lib/gitlab/testing/request_inspector_middleware.rb:35:in `call'
     # ./lib/gitlab/testing/robots_blocker_middleware.rb:30:in `call'
     # ./lib/gitlab/testing/request_blocker_middleware.rb:47:in `call'
     # ./lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'
     # ./lib/gitlab/middleware/sidekiq_web_static.rb:20:in `call'
     # ./lib/gitlab/metrics/requests_rack_middleware.rb:77:in `call'
     # ./spec/initializers/lograge_spec.rb:43:in `block (3 levels) in <main>'
     # ./spec/initializers/lograge_spec.rb:108:in `block (4 levels) in <main>'
     # ./spec/spec_helper.rb:413:in `block (3 levels) in <top (required)>'
     # ./spec/support/sidekiq_middleware.rb:18:in `with_sidekiq_server_middleware'
     # ./spec/spec_helper.rb:405:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:401:in `block (3 levels) in <top (required)>'
     # ./lib/gitlab/application_context.rb:59:in `with_raw_context'
     # ./spec/spec_helper.rb:401:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:241:in `block (2 levels) in <top (required)>'
     # ./spec/support/system_exit_detected.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/flaky_tests.rb:27:in `block (2 levels) in <main>'
     # ./spec/support/database/prevent_cross_joins.rb:106:in `block (3 levels) in <main>'
     # ./spec/support/database/prevent_cross_joins.rb:60:in `with_cross_joins_prevented'
     # ./spec/support/database/prevent_cross_joins.rb:106:in `block (2 levels) in <main>'
Finished in 6.62 seconds (files took 47.62 seconds to load)
1 example, 1 failure
  • rspec ./spec/lib/gitlab/instrumentation_helper_spec.rb:132
Failures:
  1) Gitlab::InstrumentationHelper.add_instrumentation_data when logging memory allocations logs memory usage metrics
     Failure/Error:
       expect(payload).to include(
         :mem_objects,
         :mem_bytes,
         :mem_mallocs
       )
       expected {:cpu_s => 0.000285, :db_cached_count => 0, :db_ci_cached_count => 0, :db_ci_count => 0, :db_ci_duration_s => 0...al_count => 0, :db_write_count => 0, :pid => 14529, :rate_limiting_gates => [], :worker_id => "process_14529"} to include :mem_objects, :mem_bytes, and :mem_mallocs
       Diff:
       @@ -1,42 +1,83 @@
       -[:mem_objects, :mem_bytes, :mem_mallocs]
       +:cpu_s => 0.000285,
       +:db_cached_count => 0,
       +:db_ci_cached_count => 0,
       +:db_ci_count => 0,
       +:db_ci_duration_s => 0.0,
       +:db_ci_replica_cached_count => 0,
       +:db_ci_replica_count => 0,
       +:db_ci_replica_duration_s => 0.0,
       +:db_ci_replica_wal_cached_count => 0,
       +:db_ci_replica_wal_count => 0,
       +:db_ci_wal_cached_count => 0,
       +:db_ci_wal_count => 0,
       +:db_count => 0,
       +:db_geo_cached_count => 0,
       +:db_geo_count => 0,
       +:db_geo_duration_s => 0.0,
       +:db_geo_wal_cached_count => 0,
       +:db_geo_wal_count => 0,
       +:db_main_cached_count => 0,
       +:db_main_count => 0,
       +:db_main_duration_s => 0.0,
       +:db_main_replica_cached_count => 0,
       +:db_main_replica_count => 0,
       +:db_main_replica_duration_s => 0.0,
       +:db_main_replica_wal_cached_count => 0,
       +:db_main_replica_wal_count => 0,
       +:db_main_wal_cached_count => 0,
       +:db_main_wal_count => 0,
       +:db_primary_cached_count => 0,
       +:db_primary_count => 0,
       +:db_primary_duration_s => 0.0,
       +:db_primary_wal_cached_count => 0,
       +:db_primary_wal_count => 0,
       +:db_replica_cached_count => 0,
       +:db_replica_count => 0,
       +:db_replica_duration_s => 0.0,
       +:db_replica_wal_cached_count => 0,
       +:db_replica_wal_count => 0,
       +:db_write_count => 0,
       +:pid => 14529,
       +:rate_limiting_gates => [],
       +:worker_id => "process_14529",
     # ./spec/lib/gitlab/instrumentation_helper_spec.rb:135:in `block (4 levels) in <main>'
     # ./spec/spec_helper.rb:413:in `block (3 levels) in <top (required)>'
     # ./spec/support/sidekiq_middleware.rb:18:in `with_sidekiq_server_middleware'
     # ./spec/spec_helper.rb:405:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:401:in `block (3 levels) in <top (required)>'
     # ./lib/gitlab/application_context.rb:59:in `with_raw_context'
     # ./spec/spec_helper.rb:401:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:368:in `block (3 levels) in <top (required)>'
     # ./lib/gitlab/with_request_store.rb:17:in `enabling_request_store'
     # ./lib/gitlab/with_request_store.rb:10:in `with_request_store'
     # ./spec/spec_helper.rb:368:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:241:in `block (2 levels) in <top (required)>'
     # ./spec/support/system_exit_detected.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/flaky_tests.rb:27:in `block (2 levels) in <main>'
     # ./spec/support/database/prevent_cross_joins.rb:106:in `block (3 levels) in <main>'
     # ./spec/support/database/prevent_cross_joins.rb:60:in `with_cross_joins_prevented'
     # ./spec/support/database/prevent_cross_joins.rb:106:in `block (2 levels) in <main>'
Finished in 3.52 seconds (files took 50.41 seconds to load)
1 example, 1 failure
Failed examples:
rspec ./spec/lib/gitlab/instrumentation_helper_spec.rb:132 # Gitlab::InstrumentationHelper.add_instrumentation_data when logging memory allocations logs memory usage metrics

How to reproduce

  1. Ensure Ruby 2.7.7 is installed by running gdk update

  2. Make a below change in spec/support/memory_instrumentation_helper.rb

     diff --git a/spec/support/memory_instrumentation_helper.rb b/spec/support/memory_instrumentation_helper.rb
 index 84ec02fa5aa0..718a1e33fad4 100644
 --- a/spec/support/memory_instrumentation_helper.rb
 +++ b/spec/support/memory_instrumentation_helper.rb
 @@ -6,7 +6,7 @@
 # - https://github.com/ruby/ruby/pull/3978
 module MemoryInstrumentationHelper
 def skip_memory_instrumentation!
 -    return if ::Gitlab::Memory::Instrumentation.available?
 +    # return if ::Gitlab::Memory::Instrumentation.available?
 
      # if we are running in CI, a test cannot be skipped
      return if ENV['CI']

  3. Run CI=true bundle exec rspec spec/lib/gitlab/memory/instrumentation_spec.rb

Edited by Nao Hashizume