Bug 2160497
| Summary: | Calling hammer concurrently raises 500 ISE error on apidoc / apipie | ||
|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Pavel Moravec <pmoravec> |
| Component: | API | Assignee: | Adam Ruzicka <aruzicka> |
| Status: | CLOSED ERRATA | QA Contact: | Peter Ondrejka <pondrejk> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 6.12.1 | CC: | aruzicka, jsenkyri, momran, pcreech |
| Target Milestone: | 6.13.0 | Keywords: | Regression, Triaged |
| Target Release: | Unused | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2023-05-03 13:24:33 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: | |||
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. 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 Verified on Sat 6.13 snap 14 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 |
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.