Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.
Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

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