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 - fatal NoMethodError and TypeError when hitting the API during startup
Summary: fatal NoMethodError and TypeError when hitting the API during startup
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Infrastructure
Version: 6.14.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: 6.14.0
Assignee: Adam Ruzicka
QA Contact: Jameer Pathan
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-05-10 08:22 UTC by Evgeni Golov
Modified: 2023-11-08 14:19 UTC (History)
2 users (show)

Fixed In Version: rubygem-apipie-rails-0.9.3
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-11-08 14:19:23 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github Apipie apipie-rails pull 822 0 None Merged Make html markup thread safe 2023-05-10 14:02:24 UTC
Red Hat Issue Tracker SAT-17691 0 None None None 2023-05-11 14:19:32 UTC
Red Hat Product Errata RHSA-2023:6818 0 None None None 2023-11-08 14:19:39 UTC

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
Note You need to log in before you can comment on or make changes to this bug.