Bug 2196775

Summary: fatal NoMethodError and TypeError when hitting the API during startup
Product: Red Hat Satellite Reporter: Evgeni Golov <egolov>
Component: InfrastructureAssignee: Adam Ruzicka <aruzicka>
Status: CLOSED ERRATA QA Contact: Jameer Pathan <jpathan>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.14.0CC: jpathan, pcreech
Target Milestone: 6.14.0Keywords: Triaged
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: rubygem-apipie-rails-0.9.3 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2023-11-08 14:19:23 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Evgeni Golov 2023-05-10 08:22:13 UTC 
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.
Comment 1 Evgeni Golov 2023-05-10 10:51:23 UTC 
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
Comment 2 Evgeni Golov 2023-05-10 12:35:17 UTC 
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'
Comment 3 Evgeni Golov 2023-05-10 12:45:04 UTC 
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'
Comment 4 Evgeni Golov 2023-05-10 12:48:37 UTC 
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!
Comment 5 Evgeni Golov 2023-05-10 12:55:41 UTC 
Adam says this is probably fixed by https://github.com/Apipie/apipie-rails/pull/822

Will try out
Comment 6 Evgeni Golov 2023-05-10 14:02:24 UTC 
using apipie-rails 1.0.0 seems to be fixing it for me
Comment 7 Jameer Pathan 2023-06-06 16:26:00 UTC 
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)
Comment 10 errata-xmlrpc 2023-11-08 14:19:23 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Important: Satellite 6.14 security and bug fix update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2023:6818