undefined method `to_sym' for nil - Server error in various pages with accordion trees

[jrafanie]

We've noticed this error in cypress testing. The symptoms show up with different trees but similar error messages.

[jrafanie]

To recreate this in a minimal environment, I've done the following:

• Create a minimalist cypress test:

describe('Overview > Reports Tests', () => {
    it('Can add, edit and delete a schedule', () => {
      for (var i = 0; i < 50; i++) {
        cy.login();
        cy.menu('Overview', 'Reports');
        cy.wait(100);
        cy.get('#control_reports_accord > .panel-title > .collapsed').click();
      }
    });
});

• Minimized it further and verified it still reoccurs:
  • Confirmed it doesn't happen if the start page is /optimization - the API notifications + dashboard widgets requests are involved - concurrent requests and session access
  • Created a dashboard with a single widget - confirmed it still happens, but we now have less requests to monitor
  • Set Settings.server.asynchronous_notifications = false to remove all /ws/notifications requests - it still occurs

[Fryguy]

Current theory is the dashboard widgets, when requested by the dashboard are still running in the background and modify the session. If the widget takes longer to render than the next page to load, it will clobber anything important from the next page.

So we think something like:

Req 1 (/dashboard)
Req 1 (completes - writes session)
  Req 2 (widget call kicked off in background)
Req 3 (/reports page + set the x_tree_node)
Req 3 (completes - writes x_tree_node to session)
  Req 2 (completes on backend - writes to session, but doesn't have x_tree_node in it's copy)
Req 4 (click reports menu - loads session, blows up because x_tree_node is not in session as expected)

So Request 2 has to be slow enough to allow Request 3 to complete, which causes the failure. Instead, if Request 3 completes after Request 2, then it writes the session with the x_tree_node and everything is fine and ready for Request 4.

(I picked x_tree_node in the example, but it could be any number of properties that are expected or even multiple)

[jrafanie]

For further diagnostics, I added dalli logging of the get/set requests:

index a590e31..c41e098 100644
--- a/lib/dalli/client.rb
+++ b/lib/dalli/client.rb
@@ -47,6 +47,7 @@ module Dalli
     #               to communicate with memcached.
     #
     def initialize(servers = nil, options = {})
+      Dalli.logger.info "Dalli::Client#initialize: servers: #{servers}, options: #{options}"
       @normalized_servers = ::Dalli::ServersArgNormalizer.normalize_servers(servers)
       @options = normalize_options(options)
       @key_manager = ::Dalli::KeyManager.new(@options)
@@ -423,7 +424,13 @@ module Dalli
       key = @key_manager.validate_key(key)

       server = ring.server_for_key(key)
-      server.request(op, key, *args)
+      server.request(op, key, *args).tap do |result|
+        time = Time.now.strftime("%Y.%m.%d.%H.%M.%S.%6N")
+        yml = Rails.root.join("#{time}_#{Thread.current.object_id.to_s(16)}.yml")
+        h = {:timestamp => time, :op => op, :key => key, :args => args, :result => result}
+        yml.write(YAML.dump(h))
+        # Dalli.logger.info "Dalli::Client#perform: op: #{op}, key: #{key}, args: #{args}, result: #{result}"
+      end
     rescue NetworkError => e
       Dalli.logger.debug { e.inspect }
       Dalli.logger.debug { 'retrying request with new server' }

[jrafanie]

[----] I, [2025-07-03T16:31:59.324135#6660:8b74]  INFO -- development: Dalli::Client#initialize: servers: 127.0.0.1:11211, options: {:namespace=>"MIQ:VMDB", :socket_max_failures=>5, :pool=>true, :threadsafe=>true, :value_max_bytes=>10485760}

[----] I, [2025-07-03T16:33:38.283966#6660:bc5c]  INFO -- development: Started GET "/" for 127.0.0.1 at 2025-07-03 16:33:38 -0400
[----] I, [2025-07-03T16:33:39.773321#6660:bc5c]  INFO -- development: Processing by DashboardController#login as HTML
[----] I, [2025-07-03T16:33:43.981135#6660:bc5c]  INFO -- development:   Rendered /Users/joerafaniello/Code/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login (Duration: 4132.2ms | Allocations: 6711634)
[----] I, [2025-07-03T16:33:43.990617#6660:bc5c]  INFO -- development:   Rendered layout /Users/joerafaniello/Code/manageiq-ui-classic/app/views/layouts/login.html.haml (Duration: 4141.7ms | Allocations: 6731813)
[----] I, [2025-07-03T16:33:43.990965#6660:bc5c]  INFO -- development: Completed 200 OK in 4218ms (Views: 4149.5ms | ActiveRecord: 28.0ms | Allocations: 6757915)

[----] I, [2025-07-03T16:33:44.643775#6660:ec220]  INFO -- development: Started POST "/dashboard/authenticate?button=login" for 127.0.0.1 at 2025-07-03 16:33:44 -0400
[----] I, [2025-07-03T16:33:44.654694#6660:ec220]  INFO -- development: Processing by DashboardController#authenticate as JS
[----] I, [2025-07-03T16:33:44.654749#6660:ec220]  INFO -- development:   Parameters: {"user_name"=>"admin", "user_password"=>"[FILTERED]", "browser_name"=>"Chrome", "browser_version"=>"138", "browser_os"=>"Mac", "user_TZO"=>"-4", "button"=>"login"}
[----] I, [2025-07-03T16:33:44.815145#6660:ec220]  INFO -- development: Completed 200 OK in 160ms (Views: 0.1ms | ActiveRecord: 90.1ms | Allocations: 99546)
[----] I, [2025-07-03T16:33:44.824712#6660:ec220]  INFO -- development: Started GET "/dashboard/show" for 127.0.0.1 at 2025-07-03 16:33:44 -0400
[----] I, [2025-07-03T16:33:44.827489#6660:ec220]  INFO -- development: Processing by DashboardController#show as HTML
[----] I, [2025-07-03T16:33:45.042318#6660:ec220]  INFO -- development:   Rendered /Users/joerafaniello/Code/manageiq-ui-classic/app/views/dashboard/_widget.html.haml (Duration: 25.0ms | Allocations: 18055)
[----] I, [2025-07-03T16:33:45.042363#6660:ec220]  INFO -- development:   Rendered /Users/joerafaniello/Code/manageiq-ui-classic/app/views/dashboard/show.html.haml within layouts/application (Duration: 29.1ms | Allocations: 24546)
[----] I, [2025-07-03T16:33:45.108653#6660:ec220]  INFO -- development:   Rendered layout /Users/joerafaniello/Code/manageiq-ui-classic/app/views/layouts/application.html.haml (Duration: 95.4ms | Allocations: 175639)
[----] I, [2025-07-03T16:33:45.108930#6660:ec220]  INFO -- development: Completed 200 OK in 281ms (Views: 79.4ms | ActiveRecord: 93.4ms | Allocations: 327674)
[----] I, [2025-07-03T16:33:45.298782#6660:ec220]  INFO -- development: Started GET "/api/notifications?expand=resources&attributes=details&sort_by=id&sort_order=desc&limit=100" for 127.0.0.1 at 2025-07-03 16:33:45 -0400

[----] I, [2025-07-03T16:33:45.298885#6660:bc5c]  INFO -- development: Started GET "/api/notifications" for 127.0.0.1 at 2025-07-03 16:33:45 -0400

[----] I, [2025-07-03T16:33:45.340423#6660:ec220]  INFO -- development: Processing by Api::NotificationsController#index as JSON

[----] I, [2025-07-03T16:33:45.340684#6660:bc5c]  INFO -- development: Processing by Api::NotificationsController#index as JSON

[----] I, [2025-07-03T16:33:45.340798#6660:ec220]  INFO -- development:   Parameters: {"expand"=>"resources", "attributes"=>"details", "sort_by"=>"id", "sort_order"=>"desc", "limit"=>"100"}

[----] I, [2025-07-03T16:33:45.436058#6660:f5744]  INFO -- development: Started GET "/report/explorer" for 127.0.0.1 at 2025-07-03 16:33:45 -0400
[----] I, [2025-07-03T16:33:45.533665#6660:f5744]  INFO -- development: Processing by ReportController#explorer as HTML

[----] I, [2025-07-03T16:33:45.558723#6660:f5b18]  INFO -- development: Started GET "/dashboard/widget_chart_data//4" for 127.0.0.1 at 2025-07-03 16:33:45 -0400
[----] I, [2025-07-03T16:33:45.582647#6660:f5b18]  INFO -- development: Processing by DashboardController#widget_chart_data as */*
[----] I, [2025-07-03T16:33:45.583778#6660:f5b18]  INFO -- development:   Parameters: {"id"=>"4"}
[----] I, [2025-07-03T16:33:45.699771#6660:f5b18]  INFO -- development: Completed 200 OK in 116ms (Views: 0.1ms | ActiveRecord: 58.2ms | Allocations: 132362)

[----] I, [2025-07-03T16:33:46.040041#6660:f5744]  INFO -- development:   Rendered /Users/joerafaniello/Code/manageiq-ui-classic/app/views/report/explorer.html.haml within layouts/application (Duration: 1.9ms | Allocations: 4837)
[----] I, [2025-07-03T16:33:46.079152#6660:f5744]  INFO -- development:   Rendered layout /Users/joerafaniello/Code/manageiq-ui-classic/app/views/layouts/application.html.haml (Duration: 41.1ms | Allocations: 72636)
[----] I, [2025-07-03T16:33:46.080111#6660:f5744]  INFO -- development: Completed 200 OK in 546ms (Views: 41.8ms | ActiveRecord: 142.0ms | Allocations: 643037)

[----] I, [2025-07-03T16:33:46.117760#6660:bc5c]  INFO -- development: Completed 200 OK in 777ms (Views: 0.1ms | ActiveRecord: 357.1ms | Allocations: 827776)

[----] I, [2025-07-03T16:33:46.117841#6660:ec220]  INFO -- development: Completed 200 OK in 777ms (Views: 0.0ms | ActiveRecord: 64.5ms | Allocations: 827403)

[----] I, [2025-07-03T16:33:46.250310#6660:f5744]  INFO -- development: Started GET "/api/notifications?expand=resources&attributes=details&sort_by=id&sort_order=desc&limit=100" for 127.0.0.1 at 2025-07-03 16:33:46 -0400

[----] I, [2025-07-03T16:33:46.250505#6660:f9380]  INFO -- development: Started GET "/api/notifications" for 127.0.0.1 at 2025-07-03 16:33:46 -0400

[----] I, [2025-07-03T16:33:46.255332#6660:f5744]  INFO -- development: Processing by Api::NotificationsController#index as JSON
[----] I, [2025-07-03T16:33:46.255430#6660:f5744]  INFO -- development:   Parameters: {"expand"=>"resources", "attributes"=>"details", "sort_by"=>"id", "sort_order"=>"desc", "limit"=>"100"}

[----] I, [2025-07-03T16:33:46.257358#6660:f9380]  INFO -- development: Processing by Api::NotificationsController#index as JSON
[----] I, [2025-07-03T16:33:46.284704#6660:f9380]  INFO -- development: Completed 200 OK in 27ms (Views: 0.0ms | ActiveRecord: 14.1ms | Allocations: 16516)

[----] I, [2025-07-03T16:33:46.285005#6660:f5744]  INFO -- development: Completed 200 OK in 30ms (Views: 0.0ms | ActiveRecord: 8.0ms | Allocations: 18217)
[----] I, [2025-07-03T16:33:46.295253#6660:f5744]  INFO -- development: Started POST "/report/tree_select?id=root&text=All%2520Saved%2520Reports" for 127.0.0.1 at 2025-07-03 16:33:46 -0400
[----] I, [2025-07-03T16:33:46.298095#6660:f5744]  INFO -- development: Processing by ReportController#tree_select as JS
[----] I, [2025-07-03T16:33:46.298131#6660:f5744]  INFO -- development:   Parameters: {"id"=>"root", "text"=>"All%20Saved%20Reports"}
[----] F, [2025-07-03T16:33:46.306423#6660:f5744] FATAL -- development: Error caught: [NoMethodError] undefined method `to_sym' for nil
/Users/joerafaniello/Code/manageiq-ui-classic/app/controllers/application_controller.rb:1997:in `block in assert_accordion_and_tree_privileges'
/Users/joerafaniello/Code/manageiq-ui-classic/app/controllers/application_controller.rb:1997:in `each'
/Users/joerafaniello/Code/manageiq-ui-classic/app/controllers/application_controller.rb:1997:in `find'
/Users/joerafaniello/Code/manageiq-ui-classic/app/controllers/application_controller.rb:1997:in `assert_accordion_and_tree_privileges'
/Users/joerafaniello/Code/manageiq-ui-classic/app/controllers/report_controller.rb:203:in `tree_select'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/abstract_controller/base.rb:224:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/rendering.rb:165:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/abstract_controller/callbacks.rb:259:in `block in process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activesupport-7.1.5.1/lib/active_support/callbacks.rb:110:in `run_callbacks'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/abstract_controller/callbacks.rb:258:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/rescue.rb:25:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/instrumentation.rb:74:in `block in process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activesupport-7.1.5.1/lib/active_support/notifications.rb:206:in `block in instrument'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activesupport-7.1.5.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activesupport-7.1.5.1/lib/active_support/notifications.rb:206:in `instrument'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/instrumentation.rb:73:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal/params_wrapper.rb:261:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activerecord-7.1.5.1/lib/active_record/railties/controller_runtime.rb:32:in `process_action'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/abstract_controller/base.rb:160:in `process'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionview-7.1.5.1/lib/action_view/rendering.rb:40:in `process'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal.rb:227:in `dispatch'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_controller/metal.rb:309:in `dispatch'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/journey/router.rb:51:in `block in serve'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/journey/router.rb:131:in `block in find_routes'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/journey/router.rb:124:in `each'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/journey/router.rb:124:in `find_routes'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/routing/route_set.rb:882:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-attack-6.5.0/lib/rack/attack.rb:113:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/routes_lazy_routes-0.4.3/lib/routes_lazy_routes/lazy_routes_middleware.rb:16:in `call'
/Users/joerafaniello/Code/manageiq/lib/request_started_on_middleware.rb:12:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/tempfile_reaper.rb:15:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/etag.rb:27:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/conditional_get.rb:40:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/head.rb:12:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/http/permissions_policy.rb:36:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/http/content_security_policy.rb:36:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/session/abstract/id.rb:266:in `context'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/session/abstract/id.rb:260:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/cookies.rb:689:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activerecord-7.1.5.1/lib/active_record/migration.rb:655:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/activesupport-7.1.5.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/railties-7.1.5.1/lib/rails/rack/logger.rb:37:in `call_app'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/railties-7.1.5.1/lib/rails/rack/logger.rb:26:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/sprockets-rails-3.5.2/lib/sprockets/rails/quiet_assets.rb:17:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/remote_ip.rb:92:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/request_id.rb:28:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/method_override.rb:24:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/runtime.rb:22:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/static.rb:25:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/rack-2.2.17/lib/rack/sendfile.rb:110:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/actionpack-7.1.5.1/lib/action_dispatch/middleware/host_authorization.rb:141:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/secure_headers-3.9.0/lib/secure_headers/middleware.rb:12:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/railties-7.1.5.1/lib/rails/engine.rb:536:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/railties-7.1.5.1/lib/rails/railtie.rb:226:in `public_send'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/railties-7.1.5.1/lib/rails/railtie.rb:226:in `method_missing'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/configuration.rb:279:in `call'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/request.rb:99:in `block in handle_request'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/thread_pool.rb:390:in `with_force_shutdown'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/request.rb:98:in `handle_request'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/server.rb:472:in `process_client'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/server.rb:254:in `block in run'
/Users/joerafaniello/.gem/ruby/3.3.7/gems/puma-6.6.0/lib/puma/thread_pool.rb:167:in `block in spawn_thread'
[----] I, [2025-07-03T16:33:46.307095#6660:f5744]  INFO -- development: Completed 200 OK in 9ms (Views: 0.2ms | ActiveRecord: 2.3ms | Allocations: 3923)

[jrafanie]

For the same logging above, here is the get|set for each, chronologically but spaced by thread id (the part just before the .yml):

% grep -E "\b(trees|set|get|key)\b" *.yml
2025.07.03.16.33.39.829367_bc5c.yml::op: :get
2025.07.03.16.33.39.829367_bc5c.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.39.830395_bc5c.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.43.991470_bc5c.yml::op: :set
2025.07.03.16.33.43.991470_bc5c.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.44.655395_ec220.yml::op: :get
2025.07.03.16.33.44.655395_ec220.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.44.815654_ec220.yml::op: :set
2025.07.03.16.33.44.815654_ec220.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.44.829480_ec220.yml::op: :get
2025.07.03.16.33.44.829480_ec220.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.45.109465_ec220.yml::op: :set
2025.07.03.16.33.45.109465_ec220.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.45.343124_bc5c.yml::op: :get
2025.07.03.16.33.45.343124_bc5c.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.45.344426_ec220.yml::op: :get
2025.07.03.16.33.45.344426_ec220.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.45.535990_f5744.yml::op: :get
2025.07.03.16.33.45.535990_f5744.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.45.584552_f5b18.yml::op: :get
2025.07.03.16.33.45.584552_f5b18.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.45.700728_f5b18.yml::op: :set
2025.07.03.16.33.45.700728_f5b18.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.46.084096_f5744.yml::op: :set
2025.07.03.16.33.46.084096_f5744.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.46.084096_f5744.yml:      trees: !ruby/hash:ActiveSupport::HashWithIndifferentAccess
# ^^^^ Tree is being set by thread f5744 in request "/report/explorer

2025.07.03.16.33.46.118316_bc5c.yml::op: :set
2025.07.03.16.33.46.118316_bc5c.yml::key: MIQ:VMDB:2::eb719...
# ^^^  /api/notifications request one of these is clearing the trees with data retrived before the trees were set in session

2025.07.03.16.33.46.119037_ec220.yml::op: :set
2025.07.03.16.33.46.119037_ec220.yml::key: MIQ:VMDB:2::eb719...
# ^^^ /api/notifications?expand=resources... request - one of these is clearing the trees with data retrived before the trees were set in session

2025.07.03.16.33.46.258086_f5744.yml::op: :get
2025.07.03.16.33.46.258086_f5744.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.46.259329_f9380.yml::op: :get
2025.07.03.16.33.46.259329_f9380.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.46.285548_f9380.yml::op: :set
2025.07.03.16.33.46.285548_f9380.yml::key: MIQ:VMDB:2::eb719...

2025.07.03.16.33.46.286828_f5744.yml::op: :set
2025.07.03.16.33.46.286828_f5744.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.46.299564_f5744.yml::op: :get
2025.07.03.16.33.46.299564_f5744.yml::key: MIQ:VMDB:2::eb719...
2025.07.03.16.33.46.309050_f5744.yml::op: :set
2025.07.03.16.33.46.309050_f5744.yml::key: MIQ:VMDB:2::eb719...

[jrafanie]

Next to do, see how we do the connection pool work in the various memcached clients through Dalli as the threadsafe / pool option "should" prevent clients from saving stale data.

[jrafanie]

connection pooling in dalli relies on rails session / pooling... need to verify we're using pooling correctly and if it actually doesn't any thread safety things... I got it down to very few requests reusing the same session...

set_global_session_data in application-controller calls session a bunch of times, need to make sure that code it's problematic. I don't see a bunch of session sets/gets from it.

Will need to see if dalli is actually writing things safely and preventing writes in different threads if another thread already wrote to it.

https://github.com/petergoldstein/dalli/blob/main/lib/rack/session/dalli.rb#L103-L106

[Fryguy]

Reading that code it's not safe at all. All it really does is check if the session id matches the persisted id (non-atomically, I should add), then writes it anyway - there's no checking if the content has changed or a lockid or anything. Since our multiple threads all share the same session id, it will just overwrite.

I wonder if the real fix is to pool the clients by session id. That way multiple threads would share the same client and would block on fetching the client from the pool. Even so, if the gets and sets are separated that won't really solve anything.

I'm wondering if @petergoldstein might be able to help here, but I don't want to ping him until we really need to.

[jrafanie]

Reading that code it's not safe at all. All it really does is check if the session id matches the persisted id (non-atomically, I should add), then writes it anyway - there's no checking if the content has changed or a lockid or anything. Since our multiple threads all share the same session id, it will just overwrite.

I wonder if the real fix is to pool the clients by session id. That way multiple threads would share the same client and would block on fetching the client from the pool. Even so, if the gets and sets are separated that won't really solve anything.

I'm wondering if @petergoldstein might be able to help here, but I don't want to ping him until we really need to.

Honestly, I'm reading the code and it looks like connection pool provides concurrency access to a pool of connections, so it ensures thread safety around access to the client. Thread safety in dalli is for thread safe access to sockets but it doesn't look to see if you're writing stale data.

From above, we have:

...
bc5c  GET MIQ:VMDB:2::eb719
ec220 GET MIQ:VMDB:2::eb719
f5744 GET MIQ:VMDB:2::eb719
f5b18 GET MIQ:VMDB:2::eb719
f5b18 SET MIQ:VMDB:2::eb719 
f5744 SET MIQ:VMDB:2::eb719 (saves with tree status) (overrides what f5b18 just saved)
bc5c  SET MIQ:VMDB:2::eb719 (overrides what f5b18 and f5744 just saved)
ec220 SET MIQ:VMDB:2::eb719 (overrides what f5b18, f5744, and bc5c just saved)
f5744 GET MIQ:VMDB:2::eb719 (tree status removed by one of the prior two SETs)
...

EDIT:

I think this demonstrates more @Fryguy said in #9515 (comment) ☝

[jrafanie]

We could do a few things:

1. Save session only if we make changes. Some of the saved changes look minimal. Not sure if that complicates TTL - keeping session alive. Doesn't solve the problem but there will be less saves.
2. Use separate keys/namespaces for UI session vs. API vs. ws, etc. I don't know how we'd do it for UI pages that do UI session requests along with API requests (think dashboard widgets). This still doesn't solve the problem as we're not preventing saving stale information but at least API requests session saves won't override UI session.
3. Put a big mutex around the session id/key/namespace access. I think that's what @Fryguy means by I wonder if the real fix is to pool the clients by session id. but it would have to somehow deal with concurrency where the client knows to rollback/redo when the session is known to be stale.
4. Make saves faster to further reduce the chance for thread safety issues.

[kbrock]

With option 1, I feel the session load/save cycle is pretty central to the way that rails works in the rack middleware. This will start to get into rails monkey patch land.

Is it possible to remove the data from the session?
Or possible to give each widget its own cache key? So when it completes the memcache entry is written, but this is separate from the other session data?

Feel like API requests should be atomic and not access the session at all.

[jrafanie]

EDIT:
🤣 I did a few more test runs and it still happens.

Premature comment below...

FYI, dalli sets threadsafe => false for connection pool based dalli clients. If you remove the pool options, the explicit threadsafe => true is honored and I cannot recreate this bug.

diff --git a/lib/manageiq/session/mem_cache_store_adapter.rb b/lib/manageiq/session/mem_cache_store_adapter.rb
index e281787e9e..d09b8abe67 100644
--- a/lib/manageiq/session/mem_cache_store_adapter.rb
+++ b/lib/manageiq/session/mem_cache_store_adapter.rb
@@ -12,7 +12,6 @@ module ManageIQ
           :key             => "_vmdb_session",
           :memcache_server => MiqMemcached.server_address,
           :namespace       => "MIQ:VMDB",
-          :pool_size       => 10,
           :value_max_bytes => 10.megabytes
         )
       end
diff --git a/lib/token_store.rb b/lib/token_store.rb
index a76bdad5ff..2e790be890 100644
--- a/lib/token_store.rb
+++ b/lib/token_store.rb
@@ -52,8 +52,7 @@ class TokenStore
     MiqMemcached.default_client_options.merge(
       {
         :namespace  => "MIQ:TOKENS:#{namespace.upcase}",
-        :expires_in => token_ttl,
-        :pool_size  => 10,
+        :expires_in => token_ttl
       }
     )
   end

I will see if I can recreate it and see how it impacts cypress tests and general navigation.