Foreman 3.5.3: undefined method `version' for nil:NilClass

olifre · April 20, 2023, 7:20am

Problem:
After upgrading from 3.5.2 to 3.5.3, all queries to the web page yield an error 500 and the following trace in the logs:

2023-04-20T09:15:06 [W|app|1670b0d7] Action failed
2023-04-20T09:15:06 [I|app|1670b0d7] Backtrace for 'Action failed' error (NoMethodError): undefined method `version' for nil:NilClass
 1670b0d7 | /usr/share/gems/gems/deface-1.5.3/lib/deface/action_view_extensions.rb:31:in `render'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/template_renderer.rb:61:in `block (2 levels) in render_template'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `block in instrument'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `instrument'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/template_renderer.rb:56:in `block in render_template'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/template_renderer.rb:75:in `render_with_layout'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/template_renderer.rb:55:in `render_template'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/template_renderer.rb:11:in `render'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/renderer.rb:61:in `render_template_to_object'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/renderer/renderer.rb:29:in `render_to_object'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:117:in `block in _render_template'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/base.rb:273:in `in_rendering_context'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:116:in `_render_template'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/streaming.rb:218:in `_render_template'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:103:in `render_to_body'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rendering.rb:52:in `render_to_body'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/renderers.rb:142:in `render_to_body'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/rendering.rb:25:in `render'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rendering.rb:36:in `render'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:46:in `block (2 levels) in render'
 1670b0d7 | /usr/share/ruby/benchmark.rb:308:in `realtime'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/core_ext/benchmark.rb:14:in `ms'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:46:in `block in render'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:86:in `cleanup_view_runtime'
 1670b0d7 | /usr/share/gems/gems/activerecord-6.1.7.3/lib/active_record/railties/controller_runtime.rb:34:in `cleanup_view_runtime'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:45:in `render'
 1670b0d7 | /usr/share/gems/gems/responders-3.0.1/lib/action_controller/responder.rb:240:in `default_render'
 1670b0d7 | /usr/share/gems/gems/responders-3.0.1/lib/action_controller/responder.rb:190:in `to_format'
 1670b0d7 | /usr/share/gems/gems/responders-3.0.1/lib/action_controller/responder.rb:165:in `respond'
 1670b0d7 | /usr/share/gems/gems/responders-3.0.1/lib/action_controller/responder.rb:158:in `call'
 1670b0d7 | /usr/share/gems/gems/responders-3.0.1/lib/action_controller/respond_with.rb:213:in `respond_with'
 1670b0d7 | /usr/share/foreman/app/controllers/api/base_controller.rb:168:in `process_success'
 1670b0d7 | /usr/share/foreman/app/controllers/api/base_controller.rb:173:in `process_response'
 1670b0d7 | /usr/share/foreman/app/controllers/api/v2/config_reports_controller.rb:44:in `create'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:228:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
 1670b0d7 | /usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 1670b0d7 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 1670b0d7 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 1670b0d7 | /usr/share/gems/gems/audited-5.0.2/lib/audited/sweeper.rb:16:in `around'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 1670b0d7 | /usr/share/gems/gems/audited-5.0.2/lib/audited/sweeper.rb:16:in `around'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:137:in `run_callbacks'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `block in instrument'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `instrument'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
 1670b0d7 | /usr/share/gems/gems/activerecord-6.1.7.3/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:165:in `process'
 1670b0d7 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:39:in `process'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:190:in `dispatch'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:254:in `dispatch'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:33:in `serve'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/mapper.rb:49:in `serve'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:50:in `block in serve'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `each'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `serve'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:842:in `call'
 1670b0d7 | /usr/share/gems/gems/apipie-dsl-2.5.0/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
 1670b0d7 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/static_dispatcher.rb:68:in `call'
 1670b0d7 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/extractor/recorder.rb:137:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 1670b0d7 | /usr/share/foreman/lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
 1670b0d7 | /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
 1670b0d7 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/tempfile_reaper.rb:15:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/etag.rb:27:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/conditional_get.rb:40:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/head.rb:12:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/permissions_policy.rb:22:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/content_security_policy.rb:19:in `call'
 1670b0d7 | /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:266:in `context'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:260:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/cookies.rb:697:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:98:in `run_callbacks'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 1670b0d7 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:37:in `call_app'
 1670b0d7 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:28:in `call'
 1670b0d7 | /usr/share/gems/gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
 1670b0d7 | /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/request_id.rb:26:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/method_override.rb:24:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/runtime.rb:22:in `call'
 1670b0d7 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/sendfile.rb:110:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/ssl.rb:77:in `call'
 1670b0d7 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/host_authorization.rb:142:in `call'
 1670b0d7 | /usr/share/gems/gems/secure_headers-6.5.0/lib/secure_headers/middleware.rb:11:in `call'
 1670b0d7 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/engine.rb:539:in `call'
 1670b0d7 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `public_send'
 1670b0d7 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `method_missing'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:74:in `block in call'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `each'
 1670b0d7 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `call'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/configuration.rb:252:in `call'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:77:in `block in handle_request'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:340:in `with_force_shutdown'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:76:in `handle_request'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/server.rb:443:in `process_client'
 1670b0d7 | /usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'
 1670b0d7 | /usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2023-04-20T09:15:06 [I|app|1670b0d7]   Rendered api/v2/errors/custom_error.json.rabl within api/v2/layouts/error_layout (Duration: 1.1ms | Allocations: 722)
2023-04-20T09:15:06 [I|app|1670b0d7]   Rendered layout api/v2/layouts/error_layout.json.erb (Duration: 1.2ms | Allocations: 781)
2023-04-20T09:15:06 [I|app|1670b0d7] Completed 500 Internal Server Error in 51ms (ActiveRecord: 17.6ms | Allocations: 13924)
2023-04-20T09:15:06 [F|app|1670b0d7]   
 1670b0d7 | NoMethodError (undefined method `version' for nil:NilClass):
 1670b0d7 |   
 1670b0d7 | app/controllers/api/v2/base_controller.rb:153:in `render_error'
 1670b0d7 | app/controllers/api/base_controller.rb:29:in `block in <class:BaseController>'
 1670b0d7 | lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
 1670b0d7 | lib/foreman/middleware/telemetry.rb:10:in `call'
 1670b0d7 | lib/foreman/middleware/logging_context_session.rb:22:in `call'
 1670b0d7 | lib/foreman/middleware/logging_context_request.rb:11:in `call'

Expected outcome:
It works…

Foreman and Proxy versions:
3.5.3

Distribution and version:
RockyLinux 8.7.

Other relevant data:
Re-running foreman-installer does not solve the issue. Also, it seems there was no release announcement yet, but packages are available in the repos.

olifre · April 20, 2023, 7:23am

Further testing revealed:

Re-starting httpd.service does not fix the issue.
Re-running foreman-installer.service does not fix the issue.
Re-starting foreman.service fixes the issue!

Probably, this was a ruby caching issue and means that the latter should be done by the package postinstall hooks during minor upgrades to prevent such issues?

evgeni · April 20, 2023, 7:31am

Our packaging does restart that service on upgrade:

# rpm -q --scripts foreman-service
…
postuninstall scriptlet (using /bin/sh):

if [ $1 -ge 1 ] ; then 
        # Package upgrade, not uninstall 
        systemctl try-restart foreman.service &>/dev/null || : 
fi

olifre · April 20, 2023, 8:02am

Thanks! I tried to find the cause in the logs — indeed, the service was successfully restarted during package installation with automated dnf updates.

However, I find this installation order in the logs:

2023-04-20T06:10:39+0200 SUBDEBUG Upgraded: foreman-service-3.5.2-1.el8.noarch
2023-04-20T06:11:01+0200 SUBDEBUG Upgraded: foreman-proxy-3.5.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: foreman-postgresql-3.5.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: foreman-libvirt-3.5.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: foreman-dynflow-sidekiq-3.5.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: foreman-3.5.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-rails-6.1.7.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-actionmailbox-6.1.7.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-actionmailer-6.1.7.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-actiontext-6.1.7.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-activestorage-6.1.7.2-1.el8.noarch
2023-04-20T06:11:02+0200 SUBDEBUG Upgraded: rubygem-activerecord-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-actioncable-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-railties-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-actionpack-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-actionview-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-activemodel-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-activejob-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: rubygem-activesupport-6.1.7.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: foreman-debug-3.5.2-1.el8.noarch
2023-04-20T06:11:03+0200 SUBDEBUG Upgraded: foreman-selinux-3.5.2-1.el8.noarch
2023-04-20T06:11:09+0200 INFO /sbin/restorecon: SELinux: Could not get canonical path for /etc/puppet/node.rb restorecon: No such file or directory.
2023-04-20T06:11:09+0200 SUBDEBUG Upgraded: foreman-release-3.5.2-1.el8.noarch
2023-04-20T06:11:09+0200 SUBDEBUG Upgraded: foreman-installer-1:3.5.2-1.el8.noarch
2023-04-20T06:11:10+0200 SUBDEBUG Upgraded: foreman-cli-3.5.2-1.el8.noarch

So probably, the service was updated and restarted first, and the gems were updated later, which explains the issue?

evgeni · April 20, 2023, 8:06am

As the main code is inside the foreman package, yes, this is indeed possible.

I wonder if we can influence the order of the package upgrades somehow, or if we need to use the same mechanism we use for plugin changes (see When should the Installer restart Puma)…

ekohl · April 20, 2023, 3:16pm

That is why we used to have restarts in every plugin. That caused other problems.

A structural resolution for this is Changes/Restart services at end of rpm transaction - Fedora Project Wiki which sadly doesn’t benefit us in the short term, but I think it’s available in EL9.

olifre · April 20, 2023, 3:21pm

Nice, that sounds like a good and clean solution!

I think having a fix in EL 9 is reasonable, instead of trying to add a workaround in EL 8, unless somebody comes up with a clean solution there. It caught us the first time in years of Foreman operation right now, so it probably won’t occur too often anymore before EL 9 is spreading more and more.