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 2160497 - Calling hammer concurrently raises 500 ISE error on apidoc / apipie
Summary: Calling hammer concurrently raises 500 ISE error on apidoc / apipie
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: API
Version: 6.12.1
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: 6.13.0
Assignee: Adam Ruzicka
QA Contact: Peter Ondrejka
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-01-12 15:43 UTC by Pavel Moravec
Modified: 2023-07-27 09:57 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-05-03 13:24:33 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 open Make html markup thread safe 2023-02-15 16:12:33 UTC
Red Hat Issue Tracker SAT-14936 0 None None None 2023-01-16 14:17:23 UTC
Red Hat Knowledge Base (Solution) 6994217 0 None None None 2023-01-16 15:57:38 UTC
Red Hat Product Errata RHSA-2023:2097 0 None None None 2023-05-03 13:24:47 UTC

Description Pavel Moravec 2023-01-12 15:43:45 UTC 
Description of problem:
Calling hammer commands concurrently, they often fail with:

Could not load the API description from the server: 
500 Internal Server Error
  - is the server down?
  - was 'foreman-rake apipie:cache' run on the server when using apipie cache? (typical production settings)
Warning: An error occured while loading module hammer_cli_foreman.


This is a regression from Sat6.11 where it works flawlessly.



Version-Release number of selected component (if applicable):
Sat 6.12
rubygem-hammer_cli_foreman-3.3.0.1-1.el8sat.noarch


How reproducible:
100%


Steps to Reproduce:
1. basically any request run concurrently, like:
for i in $(seq 1 10); do hammer organization list & done


Actual results:
1. Sometimes it raises:
Could not load the API description from the server: 
500 Internal Server Error
  - is the server down?
  - was 'foreman-rake apipie:cache' run on the server when using apipie cache? (typical production settings)
Warning: An error occured while loading module hammer_cli_foreman.

while production.log logs:
2023-01-12T16:24:04 [I|app|e62656af] Started GET "/apidoc/v2.en.json" for 10.44.129.103 at 2023-01-12 16:24:04 +0100
2023-01-12T16:24:04 [I|app|e62656af] Processing by Apipie::ApipiesController#index as JSON
2023-01-12T16:24:04 [I|app|e62656af]   Parameters: {"version"=>"v2.en.json", "apipy"=>{}}
2023-01-12T16:24:04 [I|app|e62656af] Completed 500 Internal Server Error in 120ms (ActiveRecord: 0.0ms | Allocations: 55386)
2023-01-12T16:24:04 [F|app|e62656af]   
 e62656af | NoMethodError (undefined method `chr' for nil:NilClass):
 e62656af |   
 e62656af | katello (4.5.0.20) lib/katello/middleware/organization_created_enforcer.rb:18:in `call'
 e62656af | katello (4.5.0.20) lib/katello/middleware/event_daemon.rb:10:in `call'
 e62656af | lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
 e62656af | lib/foreman/middleware/telemetry.rb:10:in `call'
 e62656af | lib/foreman/middleware/logging_context_session.rb:22:in `call'
 e62656af | lib/foreman/middleware/logging_context_request.rb:11:in `call'
 e62656af | katello (4.5.0.20) lib/katello/prevent_json_parsing.rb:12:in `call'


Also some GET requests to /apidoc/v2.json fail, see summary per httpd logs of all requests:

10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/apipie_checksum HTTP/1.1" 200 59 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:59 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:59 +0100] "GET /apidoc/v2.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:59 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:01 +0100] "GET /apidoc/v2.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:01 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:02 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:03 +0100] "GET /apidoc/v2.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:02 +0100] "GET /apidoc/v2.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:06 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1757834 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:10 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:10 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:03 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1757974 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:07 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:58 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1757469 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:00 +0100] "GET /apidoc/v2.json HTTP/1.1" 200 1758010 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:26:59 +0100] "GET /apidoc/v2.json HTTP/1.1" 200 1758356 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:12 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:07 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:08 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:14 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:15 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:15 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:16 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:11 +0100] "GET /apidoc/v2.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:15 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:18 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:15 +0100] "GET /katello/api/organizations HTTP/1.1" 200 306 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:13 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:15 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:20 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:13 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 500 46 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:14 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1757931 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:22 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:18 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:19 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:19 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:19 +0100] "GET /apidoc/v2.en.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:24 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:21 +0100] "GET /apidoc/v2.json HTTP/1.1" 200 1758013 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"
10.44.129.103 - - [12/Jan/2023:16:27:25 +0100] "GET /katello/api/organizations?page=1&per_page=1000 HTTP/1.1" 200 308 "-" "rest-client/2.0.2 (linux x86_64) ruby/2.7.6p219"


Expected results:
hammer commands run concurrently


Additional info:
The bug isn't in hammer, as yet simplified but artificial reproducer is:

for i in $(seq 1 10); do curl -s -H "Content-Type:application/json" -u admin:$ADMINPASS https://${hname}/apidoc/v2.en.json & done

.. and running "foreman-rake apipie:cache" does *not* help here.
Comment 1 Pavel Moravec 2023-01-16 15:52:23 UTC 
Workaround: run a hammer command sequentially and ensure ~/.cache/apipie_bindings/*/v2/*json file exists / has recent mtime. Then even concurrent hammer requests start to flawlessly work.

Reasoning: in https://access.redhat.com/solutions/6994217 (ofedoren++).

Not sure if/what (or how) is needed to fix - leaving the decision on PrdM / engineering. The user experience *is* ugly, but it is a chicken-egg kind of problem to fix, with a simple workaround. And customers *usually* won't fire concurrent hammer requests as the very first hammer command.
Comment 3 Adam Ruzicka 2023-02-16 09:48:54 UTC 
We're currently on apipie-rails-0.8.1, latest upstream is 0.9.1. Moving on to latest (once a version with the fix is released) would be nice, but we don't know when that will happen. Shall we carry the patch in our packaging for 6.13 and move to whatever is latest in upstream for 6.14?

And sorry about dropping the triaged keyword, that happened by accident
Comment 4 Peter Ondrejka 2023-03-15 15:49:32 UTC 
Verified on Sat 6.13 snap 14
Comment 7 errata-xmlrpc 2023-05-03 13:24:33 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.13 Release), 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:2097
Note You need to log in before you can comment on or make changes to this bug.