-
Bug
-
Resolution: Unresolved
-
Undefined
-
None
-
6.15.z
-
None
Description of problem:
Running multiple OpenScap Scans against the same host in a foreman job execution repeatedly returns a 422 Unprocessable Entity for one of the reports if it has the same date value as a previous report. The production.log shows Report time has already been taken. The issue is because the date field (which is a Linux Epocy Timestamp) in the POST request for 2 of the reports is the same. This prevents foreman from getting the compliance report for any report that has the same date value as a previous report.
With regular logging, we don't see the 422 error in the foreman-proxy/proxy.log, but we do see it in the foreman/production.log and the httpd/foreman-ssl_access.log. However, if we enable debug logging, we do see the 422 reponse in the proxy.log, even though there is a 200 reponse right after. We also notice that the file doesn't get stored in the reports dir in the proxy.log.
In the proxy.log with DEBUG we see the 2 reports with the same epoch time stamp. The report 5 is succesful, and we see the report stored in the reports dir. But with report 8, we don't see the report get stored, and we see both a 422 reponse and a 200 response (which is misleading if you don't have debug enabled):
Report 5 proxy.log:
2024-11-14T15:27:11 0ad12559 [I] Started POST /compliance/arf/5
2024-11-14T15:27:11 0ad12559 [D] File /var/lib/foreman-proxy/openscap/reports/arf/f274040e-8794-461d-9ae9-ae616313bbdf/158/1731616031/0954999f7b8f83c407b248059c1927cb92819f250505f1966719b9dcb92a087d stored in reports dir.
2024-11-14T15:27:11 0ad12559 [I] Finished POST /compliance/arf/5 with 200 (167.35 ms)
Report 8 proxy.log:
2024-11-14T15:27:11 1c0d8139 [I] Started POST /compliance/arf/8
2024-11-14T15:27:11 1c0d8139 [D] Received response: 422 Unprocessable Content
2024-11-14T15:27:11 1c0d8139 [D] {"result":"fail","errors":"Report time has already been taken"}
2024-11-14T15:27:11 1c0d8139 [I] Finished POST /compliance/arf/8 with 200 (165.85 ms)
In the apache logs we see the correct responses for report 5 and 8:
192.168.0.10 - - [14/Nov/2024:15:27:11 -0500] "POST /api/v2/compliance/arf_reports/f274040e-8794-461d-9ae9-ae616313bbdf/5/1731616031 HTTP/1.1" 200 26 "-" "Ruby" 192.168.0.10 - - [14/Nov/2024:15:27:11 -0500] "POST /api/v2/compliance/arf_reports/f274040e-8794-461d-9ae9-ae616313bbdf/8/1731616031 HTTP/1.1" 422 63 "-" "Ruby"
In the production.logs, the POST request for report 5 is successful, but report 8 gets the 422 error, with the response Report time has already been taken (both API request have the same date value of 1731616031:
Report 5 production.log:
2024-11-14T15:27:11 [I|app|4a0be5fa] Started POST "/api/v2/compliance/arf_reports/f274040e-8794-461d-9ae9-ae616313bbdf/5/1731616031" for 192.168.0.10 at 2024-11-14 15:27:11 -0500 2024-11-14T15:27:11 [I|app|4a0be5fa] Processing by Api::V2::Compliance::ArfReportsController#create as JSON 2024-11-14T15:27:11 [I|app|4a0be5fa] Parameters: {"logs"=>"[FILTERED]", "digest"=>"0954999f7b8f83c407b248059c1927cb92819f250505f1966719b9dcb92a087d", "metrics"=>{"passed"=>3, "failed"=>0, "othered"=>0}, "score"=>100.0, "openscap_proxy_name"=>"satellite.example.com", "openscap_proxy_url"=>"https://satellite.example.com:9090", "apiv"=>"v2", "cname"=>"f274040e-8794-461d-9ae9-ae616313bbdf", "policy_id"=>"5", "date"=>"1731616031", "arf_report"=>{"logs"=>"[FILTERED]", "digest"=>"0954999f7b8f83c407b248059c1927cb92819f250505f1966719b9dcb92a087d", "metrics"=>{"passed"=>3, "failed"=>0, "othered"=>0}, "score"=>100.0, "openscap_proxy_name"=>"satellite.example.com", "openscap_proxy_url"=>"https://satellite.example.com:9090"}} 2024-11-14T15:27:11 [D|app|4a0be5fa] Client sent certificate with subject 'satellite.example.com' and subject alt names '["satellite.example.com"]' 2024-11-14T15:27:11 [D|app|4a0be5fa] CN and SANs were extracted from a client certificate. 2024-11-14T15:27:11 [D|app|4a0be5fa] Verifying request from ["satellite.example.com"] against ["satellite.example.com"] 2024-11-14T15:27:11 [D|app|4a0be5fa] Body: {"result":"ok","id":"158"} 2024-11-14T15:27:11 [I|app|4a0be5fa] Completed 200 OK in 132ms (Views: 0.3ms | ActiveRecord: 33.4ms | Allocations: 29478)
Report 8 production.log:
2024-11-14T15:27:11 [I|app|f3a45a0a] Started POST "/api/v2/compliance/arf_reports/f274040e-8794-461d-9ae9-ae616313bbdf/8/1731616031" for 192.168.0.10 at 2024-11-14 15:27:11 -0500 2024-11-14T15:27:11 [I|app|f3a45a0a] Processing by Api::V2::Compliance::ArfReportsController#create as JSON 2024-11-14T15:27:11 [I|app|f3a45a0a] Parameters: {"logs"=>"[FILTERED]", "digest"=>"0c87945d162f4e8f858251b67807eb1d9256f066355f43f29c557b10134e2345", "metrics"=>{"passed"=>2, "failed"=>1, "othered"=>0}, "score"=>66.666664, "openscap_proxy_name"=>"satellite.example.com", "openscap_proxy_url"=>"https://satellite.example.com:9090", "apiv"=>"v2", "cname"=>"f274040e-8794-461d-9ae9-ae616313bbdf", "policy_id"=>"8", "date"=>"1731616031", "arf_report"=>{"logs"=>"[FILTERED]", "digest"=>"0c87945d162f4e8f858251b67807eb1d9256f066355f43f29c557b10134e2345", "metrics"=>{"passed"=>2, "failed"=>1, "othered"=>0}, "score"=>66.666664, "openscap_proxy_name"=>"satellite.example.com", "openscap_proxy_url"=>"https://satellite.example.com:9090"}} 2024-11-14T15:27:11 [D|app|f3a45a0a] Client sent certificate with subject 'satellite.example.com' and subject alt names '["satellite.example.com"]' 2024-11-14T15:27:11 [D|app|f3a45a0a] CN and SANs were extracted from a client certificate. 2024-11-14T15:27:11 [D|app|f3a45a0a] Verifying request from ["satellite.example.com"] against ["satellite.example.com"] 2024-11-14T15:27:11 [E|app|f3a45a0a] Report time has already been taken 2024-11-14T15:27:11 [D|app|f3a45a0a] Body: {"result":"fail","errors":"Report time has already been taken"} 2024-11-14T15:27:11 [I|app|f3a45a0a] Completed 422 Unprocessable Entity in 129ms (Views: 0.4ms | ActiveRecord: 36.5ms | Allocations: 36070)
Ansible playbook output from dynflow console which shows 422 "Unprocessable Content":
proxy_output:
result:
- output_type: stdout
output: |
DEBUG: running: oscap xccdf eval --local-files /root --results-arf /tmp/d20241114-1050918-c7kina/results.xml /var/lib/openscap/content/855bac7ef694a609a4481cf8a61bd90c53607cd5d534e98bf187ecbb4d6b13df.xml
DEBUG: running: /usr/bin/env bzip2 /tmp/d20241114-1050918-c7kina/results.xml
Uploading results to https://satellite.example.com:9090/compliance/arf/2
Report uploaded, report id: 156
DEBUG: running: oscap xccdf eval --local-files /root --results-arf /tmp/d20241114-1050947-ved5pf/results.xml /var/lib/openscap/content/2f55b4bd37cd4532aa54b4ab7e23802ba8dadd9cf398d08ad2a0dc742c392484.xml
DEBUG: running: /usr/bin/env bzip2 /tmp/d20241114-1050947-ved5pf/results.xml
timestamp: 1731616031.3003027
- output_type: stdout
output: |
Uploading results to https://satellite.example.com:9090/compliance/arf/5
Report uploaded, report id: 158
DEBUG: running: oscap xccdf eval --local-files /root --results-arf /tmp/d20241114-1050975-b8iiip/results.xml /var/lib/openscap/content/1d490efbd15f547f26c6310c7505acb5f4fb271643f47378e1499be4dee6c7ca.xml
DEBUG: running: /usr/bin/env bzip2 /tmp/d20241114-1050975-b8iiip/results.xml
Uploading results to https://satellite.example.com:9090/compliance/arf/8
Report not uploaded from proxy to Foreman server, cause: 422 "Unprocessable Content"
timestamp: 1731616032.3028705
runner_id: c9a3f822-1f67-4407-98c5-a462f6a64c7f
exit_status: 0
How reproducible:
every time foreman-proxy tries to POST 2 arf_reports with identical date value (which happens frequently in customer environment).
Is this issue a regression from an earlier version:
Steps to Reproduce:
1. run an openscan against a host with several scap policies (customer is using 3 policies)
2. the reports will need to have identical "date" values in the POST request
Actual behavior:
[Describe the issue in detail, including what is happening and where]
2. if the date value is the same for 2 reports, the latter POST request will show the 422 error
Expected behavior:
[Describe what should be happening instead]
The identical timestamp shouldn't matter, and a 422 error should not be returned.
Business Impact / Additional info:
reports are not successfully logged in Satellite
