OpenSCAP uploads producing response code 500 from proxy

Trey_Dockendorf · July 23, 2018, 2:23pm

Problem:
Several OpenSCAP clients are getting errors uploading reports to their proxy.

    Jul 23 01:00:02 webtest06 foreman_scap_client: DEBUG: running: oscap xccdf eval --fetch-remote-resources --profile xccdf_edu.osc_profile_nist-800-171-cui --tailoring-file /var/lib/openscap/tailoring/e3c97
8ef607617c0df7c8ee9f6d7b46ed033d71ac51f74b52512d8ad83ec8902.xml --results-arf /tmp/d20180723-122978-1gu4dkb/results.xml /var/lib/openscap/content/96c2a9d5278d5da905221bbb2dc61d0ace7ee3d97f021fccac994d2629
6d986d.xml
Jul 23 01:00:02 webtest06 oscap: Evaluation started. Content: /var/lib/openscap/content/96c2a9d5278d5da905221bbb2dc61d0ace7ee3d97f021fccac994d26296d986d.xml, Profile: xccdf_edu.osc_profile_nist-800-171-cu
i.
Jul 23 01:00:06 webtest06 foreman_scap_client: Downloading: https://www.redhat.com/security/data/oval/com.redhat.rhsa-RHEL7.xml.bz2 ... ok
Jul 23 01:03:46 webtest06 oscap: Evaluation finished. Return code: 2, Base score 66.853256.
Jul 23 01:03:47 webtest06 foreman_scap_client: DEBUG: running: /usr/bin/bzip2 /tmp/d20180723-122978-1gu4dkb/results.xml
Jul 23 01:04:02 webtest06 foreman_scap_client: Uploading results to https://names3.OMIT:8443/compliance/arf/3
Jul 23 01:04:02 webtest06 foreman_scap_client: <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0//EN">
Jul 23 01:04:02 webtest06 foreman_scap_client: <HTML>
Jul 23 01:04:02 webtest06 foreman_scap_client:  <HEAD><TITLE>Internal Server Error</TITLE></HEAD>
Jul 23 01:04:02 webtest06 foreman_scap_client:  <BODY>
Jul 23 01:04:02 webtest06 foreman_scap_client:    <H1>Internal Server Error</H1>
Jul 23 01:04:02 webtest06 foreman_scap_client:    no implicit conversion of Float into String
Jul 23 01:04:02 webtest06 foreman_scap_client:    <HR>
Jul 23 01:04:02 webtest06 foreman_scap_client:    <ADDRESS>
Jul 23 01:04:02 webtest06 foreman_scap_client:      at
Jul 23 01:04:02 webtest06 foreman_scap_client:     names3.OMIT:8443
Jul 23 01:04:02 webtest06 foreman_scap_client:    </ADDRESS>
Jul 23 01:04:02 webtest06 foreman_scap_client:  </BODY>
Jul 23 01:04:02 webtest06 foreman_scap_client: </HTML>
Jul 23 01:04:02 webtest06 foreman_scap_client: Upload failed: 500 "Internal Server Error "

Proxy logs around the event:

D, [2018-07-23T01:04:02.373016 ] DEBUG -- : File /var/lib/foreman-proxy/openscap/reports/arf/webtest06.OMIT/274175/1532322236/e83c39c4eda2ca1a802385d2959d21a32842377c7617da23202889db2d8a4676 stored in reports dir.
I, [2018-07-23T01:04:02.373566 ]  INFO -- : ::ffff:192.OMIT - - [23/Jul/2018:01:04:02 -0400] "POST /compliance/arf/3 HTTP/1.1" 200 - 5.8265

E, [2018-07-23T01:04:02.373637 ] ERROR -- : no implicit conversion of Float into String (TypeError)
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:113:in `block in service'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:112:in `service'
/usr/share/ruby/webrick/httpserver.rb:138:in `service'
/usr/share/ruby/webrick/httpserver.rb:94:in `run'
/usr/share/ruby/webrick/server.rb:295:in `block in start_thread'
D, [2018-07-23T01:04:02.374109 ] DEBUG -- : close: ::ffff:192.OMIT:35942

Expected outcome:

I’d expect all like hosts with same policies to upload to same proxy successfully.

Foreman and Proxy versions:
Foreman proxy 1.15.6 and Foreman 1.17.1

Proxy version is lagging to work around bug that caused DHCP parsing to break.

Foreman and Proxy plugin versions:

rubygem-foreman_scap_client-0.3.0-1.el7.noarch
rubygem-smart_proxy_openscap-0.6.8-1.el7.noarch

Other relevant data:

Worth noting we have approximately 18 hosts all uploading their reports to the same smart proxy at the same time via the Foreman puppet module for openscap clients. Maybe this issue is an issue where too many uploads hit the proxy at the same time? If this is the case then maybe a patch would need to be added to Puppet module to randomize runtimes? The majority of the uploads are successful and the failures are not always on the same host. Ad-hoc uploads using foreman_scap_client are successful from the hosts that fail via cron.

Ondrej_Prazak · July 24, 2018, 6:13am

Thanks for reporting this. I have not encountered this before, it might be a performance issue as you suggest. I’ll try to set up large number of hosts to see if I can reproduce. Configuring clients so that all of them would not send reports at the same time is definitely something we would like to have in the future, it is already tracked in Redmine.

Trey_Dockendorf · July 30, 2018, 12:20pm

Running with latest splay changes to foreman_scap_client Puppet module and still seeing 500 errors. From the looks of it I may have just gotten really unlucky and had two reports upload at the same time. Is this something that can be fixed on the proxy side to better handle concurrent SCAP report uploads?

Ondrej_Prazak · July 31, 2018, 5:47am

It should be fixed so that proxy accepts the uploaded reports and does not return 500, but I am not sure what is going on there yet.

Trey_Dockendorf · August 27, 2018, 4:04pm

I deployed latest Puppet module with splay of 1 hour and still getting occasional errors. I have 3 proxies that handle SCAP uploads and this particular proxy only has 20 hosts uploading reports with a splay of 1 hour. The last failure doesn’t appear to be concurrency related since there are several minutes before and after the failed request.

I notice start_thread in back trace. Does the number of threads allowed correspond to number of CPUs available to the proxy? These proxies only have 2 vCPUs.

D, [2018-08-27T01:44:38.420700 ] DEBUG -- : accept: ::ffff:OMIT:60036
D, [2018-08-27T01:44:38.422234 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-08-27T01:44:38.438126 ] DEBUG -- : Executing: smart-proxy-arf-json /var/tmp/687dc07f-8e98-4484-91b0-c4ef788904b6-web06.OMIT-3-1535348678-20180827-6445-1gd92f6 /var/tmp/687dc07f-8e98-4484-91b0-c4ef788904b6-web06.OMIT-3-1535348678-json-20180827-6445-53p4uf
D, [2018-08-27T01:44:44.029609 ] DEBUG -- : File /var/lib/foreman-proxy/openscap/reports/arf/web06.OMIT/290933/1535348678/b405cf62f4ab373f3a55879bea56f9edf511694c6eb6f328882cd8bd1c5dbd7b stored in reports dir.
I, [2018-08-27T01:44:44.030096 ]  INFO -- : ::ffff:OMIT - - [27/Aug/2018:01:44:44 -0400] "POST /compliance/arf/3 HTTP/1.1" 200 - 5.5943

D, [2018-08-27T01:44:44.030550 ] DEBUG -- : close: ::ffff:OMIT:60036
D, [2018-08-27T01:49:03.445712 ] DEBUG -- : accept: ::ffff:10.20.0.1:57478
D, [2018-08-27T01:49:03.448560 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
I, [2018-08-27T01:49:03.450231 dcdfb31b]  INFO -- : ::ffff:10.20.0.1 - - [27/Aug/2018:01:49:03 -0400] "GET /version HTTP/1.1" 200 114 0.0008

D, [2018-08-27T01:49:03.490604 ] DEBUG -- : close: ::ffff:10.20.0.1:57478
D, [2018-08-27T01:52:30.314227 ] DEBUG -- : accept: ::ffff:OMIT:47750
D, [2018-08-27T01:52:30.315665 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-08-27T01:52:30.326789 ] DEBUG -- : Executing: smart-proxy-arf-json /var/tmp/e1af8ebf-b7b7-4988-92c5-a6d396d2a0bb-web05.OMIT-4-1535349150-20180827-6445-6czaw8 /var/tmp/e1af8ebf-b7b7-4988-92c5-a6d396d2a0bb-web05.OMIT-4-1535349150-json-20180827-6445-1la1k1o
D, [2018-08-27T01:52:34.688769 ] DEBUG -- : File /var/lib/foreman-proxy/openscap/reports/arf/web05.OMIT/290936/1535349150/c574bce3c54a260ce02ffbf6f25f6d4314389b11a0f8127a058cbd3cad9ac270 stored in reports dir.
I, [2018-08-27T01:52:34.689326 ]  INFO -- : ::ffff:OMIT - - [27/Aug/2018:01:52:34 -0400] "POST /compliance/arf/4 HTTP/1.1" 200 - 4.3647

E, [2018-08-27T01:52:34.689398 ] ERROR -- : no implicit conversion of Float into String (TypeError)
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:113:in `block in service'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/body_proxy.rb:31:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:112:in `service'
/usr/share/ruby/webrick/httpserver.rb:138:in `service'
/usr/share/ruby/webrick/httpserver.rb:94:in `run'
/usr/share/ruby/webrick/server.rb:295:in `block in start_thread'
D, [2018-08-27T01:52:34.689919 ] DEBUG -- : close: ::ffff:OMIT:47750
D, [2018-08-27T01:56:12.162066 ] DEBUG -- : accept: ::ffff:OMIT:41606
D, [2018-08-27T01:56:12.164888 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-08-27T01:56:12.179791 ] DEBUG -- : Executing: smart-proxy-arf-json /var/tmp/02dd61a4-7b93-4db7-b608-c5ec2b80ead7-web02.OMIT-4-1535349372-20180827-6445-1yo29s5 /var/tmp/02dd61a4-7b93-4db7-b608-c5ec2b80ead7-web02.OMIT-4-1535349372-json-20180827-6445-b5zfa9
D, [2018-08-27T01:56:17.595364 ] DEBUG -- : File /var/lib/foreman-proxy/openscap/reports/arf/web02.OMIT/290937/1535349372/ef6f6094e17254f25baaa957c88ba9a423698ce8c9088b241bc3dd6df9a18965 stored in reports dir.
I, [2018-08-27T01:56:17.595848 ]  INFO -- : ::ffff:OMIT - - [27/Aug/2018:01:56:17 -0400] "POST /compliance/arf/4 HTTP/1.1" 200 - 5.4195

D, [2018-08-27T01:56:17.596287 ] DEBUG -- : close: ::ffff:OMIT:41606

Ondrej_Prazak · August 28, 2018, 1:50pm

If the proxy runs on both http and https, the proxy launcher starts a thread for each:

github.com

theforeman/smart-proxy/blob/develop/lib/launcher.rb#L157-L188


def launch
  raise Exception.new("Both http and https are disabled, unable to start.") unless http_enabled? || https_enabled?


  if settings.daemon
    check_pid
    Process.daemon
    write_pid
  end


  ::Proxy::PluginInitializer.new(::Proxy::Plugins.instance).initialize_plugins


  http_app = http_app(settings.http_port)
  https_app = https_app(settings.https_port)
  install_webrick_callback!(http_app, https_app)


  t1 = Thread.new { webrick_server(https_app, settings.bind_host, settings.https_port).start } unless https_app.nil?
  t2 = Thread.new { webrick_server(http_app, settings.bind_host, settings.http_port).start } unless http_app.nil?


  Proxy::SignalHandler.install_traps

This file has been truncated. show original

Trey_Dockendorf · August 28, 2018, 2:13pm

So sounds like lack of threads is not the issue. My instance is only configured for https. Any debugging I can perform that would be helpful in understanding this problem and possibly helping come up with a fix? The backtrace appears to be in webrick and rack so not sure if anything on proxy side could be patched to improve this behavior.

Ondrej_Prazak · August 29, 2018, 6:14am

Based on the trace it looks like it could be a problem in webrick. If that is really the case, we would need to fix it there to make the report upload more stable.

Trey_Dockendorf · August 29, 2018, 8:01pm

I just discovered by doing manual executions of foreman_scap_client that the uploads generating 500 responses are successful and accessible via web interface, at least in my interactive attempts. I’ll open an issue once I’ve upgraded to 1.17.3. My proxies are forced back to 1.15.6 to work around a DHCP parsing bug that should now be fixed.