Bug #36329
Updated by Alex Kinneer over 1 year ago
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: <pre> --- 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 </pre> ====================== Log exception example: <pre> 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) </pre>