Project

General

Profile

Actions

Bug #36329

closed

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

Added by Alex Kinneer over 1 year ago. Updated about 1 year 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

Also available in: Atom PDF