Project

General

Profile

Actions

Bug #36329

closed

Cache reads from redis raise "incompatible marshal file format" exception

Added by Alex Kinneer about 1 year ago. Updated 9 months ago.

Status:
Closed
Priority:
Normal
Assignee:
Category:
Notifications
Target version:
-
Difficulty:
Triaged:
Yes
Fixed in Releases:
Found in Releases:

Description

Foreman writes notification data to the (redis) cache as raw JSON, but then attempts to read them back using the cache default format (Ruby marshaling). This results in the UI failing to display some notifications, and persistent errors in the log that look like the example shown below. It appears it can be resolved with a one-line fix in the cache_handler to change it to pass the same "raw" parameter for reads as is used for writes:

--- cache_handler.rb    2023-04-20 18:18:46.854217570 +0000
+++ /usr/share/foreman/app/services/ui_notifications/cache_handler.rb    2023-04-20 18:14:29.467040707 +0000
@@ -7,7 +7,7 @@

     # JSON Payload
     def payload
-      result = cache.read(cache_key)
+      result = cache.read(cache_key, raw: true)
       if result
         logger.debug("Cache Hit: notification, reading cache for #{cache_key}")
         return result

======================
Log exception example:

2023-04-19T21:35:12 [I|app|b69e4848] Backtrace for 'Action failed' error (TypeError): incompatible marshal file format (can't be read)
        format version 4.8 required; 123.34 given
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/core_ext/marshal.rb:8:in `load'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/core_ext/marshal.rb:8:in `load'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache.rb:598:in `deserialize_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/redis_cache_store.rb:459:in `deserialize_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/redis_cache_store.rb:349:in `block in read_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/redis_cache_store.rb:478:in `failsafe'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/redis_cache_store.rb:347:in `read_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache.rb:136:in `block in read_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache.rb:78:in `block in fetch_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache.rb:78:in `fetch'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache.rb:78:in `fetch_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache.rb:134:in `read_entry'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache.rb:367:in `block in read'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache.rb:726:in `block in instrument'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:205:in `instrument'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache.rb:726:in `instrument'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache.rb:366:in `read'
/usr/share/foreman/app/services/ui_notifications/cache_handler.rb:10:in `payload'
/usr/share/foreman/app/controllers/notification_recipients_controller.rb:7:in `index'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:228:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/usr/share/gems/gems/audited-5.3.1/lib/audited/sweeper.rb:16:in `around'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/usr/share/gems/gems/audited-5.3.1/lib/audited/sweeper.rb:16:in `around'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:137:in `run_callbacks'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `block in instrument'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `instrument'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
/usr/share/gems/gems/activerecord-6.1.7.3/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:165:in `process'
/usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:39:in `process'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:190:in `dispatch'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:254:in `dispatch'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `each'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `serve'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:842:in `call'
/usr/share/gems/gems/apipie-dsl-2.5.0/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/static_dispatcher.rb:68:in `call'
/usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
/usr/share/foreman/lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/etag.rb:27:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/conditional_get.rb:27:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/head.rb:12:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/permissions_policy.rb:22:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/content_security_policy.rb:19:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/session/abstract/id.rb:266:in `context'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/session/abstract/id.rb:260:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/cookies.rb:697:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:37:in `call_app'
/usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:28:in `call'
/usr/share/gems/gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/request_id.rb:26:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/method_override.rb:24:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/runtime.rb:22:in `call'
/usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/sendfile.rb:110:in `call'
/usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/host_authorization.rb:142:in `call'
/usr/share/gems/gems/secure_headers-6.5.0/lib/secure_headers/middleware.rb:11:in `call'
/usr/share/gems/gems/railties-6.1.7.3/lib/rails/engine.rb:539:in `call'
/usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `public_send'
/usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `method_missing'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:74:in `block in call'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:58:in `each'
/usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:58:in `call'
/usr/share/gems/gems/puma-5.6.5/lib/puma/configuration.rb:252:in `call'
/usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:77:in `block in handle_request'
/usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:340:in `with_force_shutdown'
/usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:76:in `handle_request'
/usr/share/gems/gems/puma-5.6.5/lib/puma/server.rb:443:in `process_client'
/usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'
/usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2023-04-19T21:35:12 [D|app|b69e4848]   Rendering layout api/v2/layouts/error_layout.json.erb
2023-04-19T21:35:12 [D|app|b69e4848]   Rendering api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout
2023-04-19T21:35:12 [I|app|b69e4848]   Rendered api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout (Duration: 0.6ms | Allocations: 246)
2023-04-19T21:35:12 [I|app|b69e4848]   Rendered layout api/v2/layouts/error_layout.json.erb (Duration: 3.6ms | Allocations: 5393)
2023-04-19T21:35:12 [I|app|b69e4848] Completed 500 Internal Server Error in 11ms (Views: 4.7ms | ActiveRecord: 0.9ms | Allocations: 7704)
Actions #1

Updated by Alex Kinneer about 1 year ago

  • Description updated (diff)
Actions #2

Updated by The Foreman Bot 10 months ago

  • Status changed from New to Ready For Testing
  • Assignee set to Eric Helms
  • Pull request https://github.com/theforeman/foreman/pull/9792 added
Actions #3

Updated by The Foreman Bot 10 months ago

  • Fixed in Releases 3.8.0 added
Actions #4

Updated by Eric Helms 10 months ago

  • Status changed from Ready For Testing to Closed
Actions #5

Updated by Ewoud Kohl van Wijngaarden 9 months ago

  • Category set to Notifications
  • Triaged changed from No to Yes
Actions

Also available in: Atom PDF