Description of problem: When the app is "starting up" (e.g. after a "systemctl restart foreman") and one hits it with many requests (like GET /api/status), one often sees errors like the following in the logs: 2023-05-10T07:53:33 [F|app|65251c92] 65251c92 | NoMethodError (undefined method `chr' for nil:NilClass): 65251c92 | 65251c92 | lib/foreman/middleware/logging_context_session.rb:22:in `call' 65251c92 | lib/foreman/middleware/logging_context_request.rb:11:in `call' 65251c92 | katello (4.9.0.pre.master) lib/katello/prevent_json_parsing.rb:12:in `call' 2023-05-10T07:53:34 [F|app|ed179145] ed179145 | TypeError (nil can't be coerced into Integer): ed179145 | ed179145 | lib/foreman/middleware/logging_context_session.rb:22:in `call' ed179145 | lib/foreman/middleware/logging_context_request.rb:11:in `call' ed179145 | katello (4.9.0.pre.master) lib/katello/prevent_json_parsing.rb:12:in `call' Version-Release number of selected component (if applicable): Reporting this for 6.14, but I have seen this on older releases too (just never bothered to report) How reproducible: often, but not always Steps to Reproduce: 1. systemctl restart foreman 2. echo 'GET https://admin:changeme@satellite.example.com/api/status' | vegeta attack -duration=10s -insecure | vegeta report (or any other http load tester, really doesn't matter, as long as it produces many parallel requests) Actual results: some requests end up with errors Expected results: no errors? Additional info: I *think* this has something to do with the app still starting up, as those runs also often have way lower "request/second" numbers than later runs that do not expose the same errors (15 vs 50 in my test env). Also, I am almost certain the stack trace in the log is a red herring, but that's all I have to offer, sorry.
Ewoud pointed me https://community.theforeman.org/t/katello-nightly-rpm-pipeline-1633-failed/33071/8 which contained some upstream investigation of a (similar?) issue
I have disabled all Katello middlewares (https://github.com/Katello/katello/blob/25061d6fb53c7303da9e666d2ad16e648a1f15ab/lib/katello/engine.rb#L9-L22) and it still reproducible. Now without the Katello middleware in the log: 2023-05-10T12:33:38 [F|app|f6f1d6fb] f6f1d6fb | NoMethodError (undefined method `chr' for nil:NilClass): f6f1d6fb | f6f1d6fb | lib/foreman/middleware/logging_context_session.rb:22:in `call' f6f1d6fb | lib/foreman/middleware/logging_context_request.rb:11:in `call'
and after disabling the foreman logging middlewares, I finally have a working trace: 2023-05-10T12:42:37 [F|app|] | NoMethodError (undefined method `chr' for nil:NilClass): | | rdoc (6.2.1.1) lib/rdoc/markup/attribute_manager.rb:329:in `split_into_flow' | rdoc (6.2.1.1) lib/rdoc/markup/attribute_manager.rb:261:in `flow' | rdoc (6.2.1.1) lib/rdoc/markup/to_html.rb:400:in `to_html' | rdoc (6.2.1.1) lib/rdoc/markup/to_html.rb:189:in `accept_paragraph' | rdoc (6.2.1.1) lib/rdoc/markup/paragraph.rb:11:in `accept' | rdoc (6.2.1.1) lib/rdoc/markup/formatter.rb:75:in `block in accept_document' | rdoc (6.2.1.1) lib/rdoc/markup/formatter.rb:70:in `each' | rdoc (6.2.1.1) lib/rdoc/markup/formatter.rb:70:in `accept_document' | rdoc (6.2.1.1) lib/rdoc/markup/document.rb:68:in `accept' | rdoc (6.2.1.1) lib/rdoc/markup.rb:822:in `convert' | rdoc (6.2.1.1) lib/rdoc/markup/formatter.rb:121:in `convert' | apipie-rails (0.8.2) lib/apipie/markup.rb:8:in `to_html' | apipie-rails (0.8.2) lib/apipie/helpers.rb:6:in `markup_to_html' | apipie-rails (0.8.2) lib/apipie/param_description.rb:267:in `preformat_text' | apipie-rails (0.8.2) lib/apipie/param_description.rb:160:in `to_json' | apipie-rails (0.8.2) lib/apipie/param_description.rb:170:in `block in to_json' | apipie-rails (0.8.2) lib/apipie/param_description.rb:170:in `map' | apipie-rails (0.8.2) lib/apipie/param_description.rb:170:in `to_json' | apipie-rails (0.8.2) lib/apipie/method_description.rb:189:in `block in to_json' | apipie-rails (0.8.2) lib/apipie/method_description.rb:189:in `map' | apipie-rails (0.8.2) lib/apipie/method_description.rb:189:in `to_json' | apipie-rails (0.8.2) lib/apipie/resource_description.rb:102:in `block in to_json' | apipie-rails (0.8.2) lib/apipie/resource_description.rb:102:in `each' | apipie-rails (0.8.2) lib/apipie/resource_description.rb:102:in `collect' | apipie-rails (0.8.2) lib/apipie/resource_description.rb:102:in `to_json' | apipie-rails (0.8.2) lib/apipie/application.rb:299:in `block in to_json' | apipie-rails (0.8.2) lib/apipie/application.rb:298:in `each' | apipie-rails (0.8.2) lib/apipie/application.rb:298:in `inject' | apipie-rails (0.8.2) lib/apipie/application.rb:298:in `to_json' | apipie-rails (0.8.2) lib/apipie/apipie_module.rb:13:in `to_json' | apipie-rails (0.8.2) lib/apipie/application.rb:356:in `block in compute_checksum' | apipie-rails (0.8.2) lib/apipie/application.rb:355:in `each' | apipie-rails (0.8.2) lib/apipie/application.rb:355:in `inject' | apipie-rails (0.8.2) lib/apipie/application.rb:355:in `compute_checksum' | apipie-rails (0.8.2) lib/apipie/application.rb:363:in `checksum' | apipie-rails (0.8.2) lib/apipie/apipie_module.rb:34:in `method_missing' | apipie-rails (0.8.2) lib/apipie/middleware/checksum_in_headers.rb:29:in `call' | rack (2.2.6.2) lib/rack/tempfile_reaper.rb:15:in `call' | rack (2.2.6.2) lib/rack/etag.rb:27:in `call' | rack (2.2.6.2) lib/rack/conditional_get.rb:27:in `call' | rack (2.2.6.2) lib/rack/head.rb:12:in `call' | actionpack (6.1.7.3) lib/action_dispatch/http/permissions_policy.rb:22:in `call' | actionpack (6.1.7.3) lib/action_dispatch/http/content_security_policy.rb:19:in `call' | rack (2.2.6.2) lib/rack/session/abstract/id.rb:266:in `context' | rack (2.2.6.2) lib/rack/session/abstract/id.rb:260:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/cookies.rb:697:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call' | activesupport (6.1.7.3) lib/active_support/callbacks.rb:98:in `run_callbacks' | actionpack (6.1.7.3) lib/action_dispatch/middleware/callbacks.rb:26:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call' | railties (6.1.7.3) lib/rails/rack/logger.rb:37:in `call_app' | railties (6.1.7.3) lib/rails/rack/logger.rb:28:in `call' | sprockets-rails (3.4.2) lib/sprockets/rails/quiet_assets.rb:13:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/remote_ip.rb:81:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/request_id.rb:26:in `call' | rack (2.2.6.2) lib/rack/method_override.rb:24:in `call' | rack (2.2.6.2) lib/rack/runtime.rb:22:in `call' | activesupport (6.1.7.3) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/executor.rb:14:in `call' | rack (2.2.6.2) lib/rack/sendfile.rb:110:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/ssl.rb:77:in `call' | actionpack (6.1.7.3) lib/action_dispatch/middleware/host_authorization.rb:142:in `call' | secure_headers (6.5.0) lib/secure_headers/middleware.rb:11:in `call' | railties (6.1.7.3) lib/rails/engine.rb:539:in `call' | railties (6.1.7.3) lib/rails/railtie.rb:207:in `public_send' | railties (6.1.7.3) lib/rails/railtie.rb:207:in `method_missing' | rack (2.2.6.2) lib/rack/urlmap.rb:74:in `block in call' | rack (2.2.6.2) lib/rack/urlmap.rb:58:in `each' | rack (2.2.6.2) lib/rack/urlmap.rb:58:in `call' | puma (5.6.5) lib/puma/configuration.rb:252:in `call' | puma (5.6.5) lib/puma/request.rb:77:in `block in handle_request' | puma (5.6.5) lib/puma/thread_pool.rb:340:in `with_force_shutdown' | puma (5.6.5) lib/puma/request.rb:76:in `handle_request' | puma (5.6.5) lib/puma/server.rb:443:in `process_client' | puma (5.6.5) lib/puma/thread_pool.rb:147:in `block in spawn_thread' | logging (2.3.1) lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
And to finalize: disabling Apipie::Middleware::ChecksumInHeaders gets rid of those errors on my reproducer AND pushes the requests/second to 50 on a cold app boot!
Adam says this is probably fixed by https://github.com/Apipie/apipie-rails/pull/822 Will try out
using apipie-rails 1.0.0 seems to be fixing it for me
Verified Verified with: - Satellite 6.14.0 snap 1 Test steps: 1. run "satellite-installer --foreman-db-pool 128" 2. systemctl restart foreman 2. echo 'GET https://admin:changeme@satellite.example.com/api/status' | vegeta attack -duration=10s -insecure | vegeta report Observations: - No errors in production.log Additional info: Saw the following on Vegeta command output: Error Set: Get "https://user:***@satellite.example.com/api/status": net/http: request canceled (Client.Timeout exceeded while awaiting headers) Get "https://user:***@satellite.example.com/api/status": context deadline exceeded (Client.Timeout exceeded while awaiting headers)