Katello: Intermittent 502 error publishing new content view version

Problem:
We have a cron job to automatically publish new content view versions once a week. Normally these work, but for a particular content view the publish REST call sometimes fails with an error code 502. Oddly enough, the content view version does end up getting published, but because the REST call returns a 502 response, the automated job fails and stops
Expected outcome:
Publishing a new content view version via the REST API returns a successful code, when it should be successful
Foreman and Proxy versions:
foreman 2.2.1
Foreman and Proxy plugin versions:
katello 3.17.0
Distribution and version:
CentOS 7.9
Other relevant data:

From foreman-ssl_access_ssl.log:

10.10.10.10 - - [30/Nov/2020:03:00:09 +0000] "POST /katello/api/content_views/11/publish HTTP/1.1" 502 452 "-" "-"

From production.log:

2020-11-30T03:00:09 [I|app|4b2d4d29] Started POST "/katello/api/content_views/11/publish" for 127.0.0.1 at 2020-11-30 03:00:09 +0000
2020-11-30T03:00:09 [I|app|4b2d4d29] Processing by Katello::Api::V2::ContentViewsController#publish as JSON
2020-11-30T03:00:09 [I|app|4b2d4d29]   Parameters: {"id"=>"11", "description"=>"2020/11/30 [auto]", "api_version"=>"v2", "content_view"=>{"id"=>"11", "description"=>"2020/11/30 [auto]"}}
2020-11-30T03:00:10 [W|app|4b2d4d29] Scoped order is ignored, it's forced to be batch order.
2020-11-30T03:00:10 [I|app|4b2d4d29] Authorized user sacpmanage(SA Common Platform Management)
2020-11-30T03:00:10 [I|bac|4b2d4d29] Task {label: Actions::Katello::ContentView::Publish, id: c51e234a-9e99-4bc1-bfa6-a9f713eb392d, execution_plan_id: f7b2e7f6-9367-48df-8b84-79d95f560248} state changed: planning

If you search the production.log for ‘4b2d4d29’ you’ll see everything that gets logged for that particular request. When doing so, what do you see reported for the response of the request? Trying to see if that matches what is in the ssl access log, and if there are any interesting errors in there along the way.

Second question is: when this publish activity is happening, what is the load on the server like? You may need to increase the resources available to the server, or see about adjusting the tuning profile via installer which does things like give more workers to the web process.

So, the production.log snippet was the result of that grep, so nothing that looked bad to me.

As for server load at the time, there doesn’t look to be anything unusual…

The publish which starts at 03:00 gives the 502 error, but completes. The next publish, which I offset to 03:30 doesn’t give a 502 error, and also completes.

There’s a lot of noise in /var/log/messages after the publish starts at 03:00, some of which would look to be associated with the publish, but I can’t see the forest for the trees…

It’s interesting. If that’s the full result of the grep, then the Rails application running under puma never came back with a response. I suppose that’s why you’re seeing a 502 in the httpd log which serves as a reverse proxy to puma. I was looking at a similar problem not too long ago but never got anywhere because I couldn’t reproduce it myself.

Are you interested in testing some possible solutions? My gut feeling is that it has to do with how we configure the ProxyPass to puma on the Foreman server.

Right now, your configuration looks like this:

ProxyPass / http://127.0.0.1:3000/ retry=0 timeout=900

I was trying to see if the below gets around it, but again I could not reproduce:

ProxyPass / http://127.0.0.1:3000/ retry=0 keepalive=On ping=30 timeout=900

or this alternative:

ProxyPass / http://127.0.0.1:3000/ disablereuse=On timeout=900

These changes would be made in /etc/httpd/conf.d/05-foreman-ssl.conf and require a restart of httpd

Thanks, I’ve made the change (the first one) and will wait for my Monday morning job to fire.

Well, unfortunately, no change after the Apache config change:

10.12.34.97 - - [07/Dec/2020:03:00:06 +0000] "POST /katello/api/content_views/11/publish HTTP/1.1" 503 144 "-" "-"

# grep 81e40cfe production.log-20201207
2020-12-07T03:00:06 [I|app|81e40cfe] Started POST "/katello/api/content_views/11/publish" for 127.0.0.1 at 2020-12-07 03:00:06 +0000
2020-12-07T03:00:06 [I|app|81e40cfe] Processing by Katello::Api::V2::ContentViewsController#publish as JSON
2020-12-07T03:00:06 [I|app|81e40cfe]   Parameters: {"id"=>"11", "description"=>"2020/12/07 [auto]", "api_version"=>"v2", "content_view"=>{"id"=>"11", "description"=>"2020/12/07 [auto]"}}
2020-12-07T03:00:07 [W|app|81e40cfe] Scoped order is ignored, it's forced to be batch order.
2020-12-07T03:00:07 [I|app|81e40cfe] Authorized user sacpmanage(SA Common Platform Management)
2020-12-07T03:00:07 [I|bac|81e40cfe] Task {label: Actions::Katello::ContentView::Publish, id: ac522f28-41ba-4fc9-a55b-2d59b7fabdf8, execution_plan_id: 27c4d314-ae74-4c75-9d14-ecf02a481c56} state changed: planning

However, I’ve now got a hunch, after seeing that the system’s logrotate is going off at around 03:00, and this publish job is starting at 03:00 too.

apache   119303  0.2  0.6 1407772 125232 ?      Sl   03:08   1:33 (wsgi:pulp)     -DFOREGROUND
apache   119304  0.2  0.6 1340956 114892 ?      Sl   03:08   1:29 (wsgi:pulp)     -DFOREGROUND
apache   119305  0.2  0.5 1341468 105156 ?      Sl   03:08   1:33 (wsgi:pulp)     -DFOREGROUND
apache   119306  0.3  0.2 737024 49720 ?        Sl   03:08   1:46 (wsgi:pulp-cont -DFOREGROUND
apache   119307  0.3  0.2 737024 49012 ?        Sl   03:08   1:46 (wsgi:pulp-cont -DFOREGROUND
apache   119308  0.3  0.2 868096 49792 ?        Sl   03:08   1:46 (wsgi:pulp-cont -DFOREGROUND
apache   119309  0.0  0.3 905024 64236 ?        Sl   03:08   0:12 (wsgi:pulp_forg -DFOREGROUND

Dec 7 03:08:28 pal212 run-parts(/etc/cron.daily)[119325]: finished logrotate

So, I’m moving the job to 02:00 to test my hunch.

Interesting! Curious to learn what will show up in production.log once we can see the full request.

OK, hunch disproved, it still gave the 503 when moved to 02:00 this morning. It does seem to be just the one content view though, the other content views which are published in the same way never fail like this.

2020-12-08T02:00:05 [I|app|6c5af6d7] Started POST "/katello/api/content_views/11/publish" for 127.0.0.1 at 2020-12-08 02:00:05 +0000
2020-12-08T02:00:05 [I|app|6c5af6d7] Processing by Katello::Api::V2::ContentViewsController#publish as JSON
2020-12-08T02:00:05 [I|app|6c5af6d7]   Parameters: {"id"=>"11", "description"=>"2020/12/08 [auto]", "api_version"=>"v2", "content_view"=>{"id"=>"11", "description"=>"2020/12/08 [auto]"}}
2020-12-08T02:00:05 [W|app|6c5af6d7] Scoped order is ignored, it's forced to be batch order.
2020-12-08T02:00:05 [I|app|6c5af6d7] Authorized user sacpmanage(SA Common Platform Management)
2020-12-08T02:00:05 [I|bac|6c5af6d7] Task {label: Actions::Katello::ContentView::Publish, id: 2813ca85-ca09-4138-b253-499f447ac1fc, execution_plan_id: 0187c4e4-ed95-4177-989b-57b6a61db9b8} state changed: planning

Details on the publish seem to be able to be found grepping for ‘|aud|’, so:

2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on content_view_id 11
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on major 88
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on definition_archive_id
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on minor 0
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on content_counts
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on repository_ids []
2020-12-08T02:00:05 [I|aud|] Katello::ContentViewVersion (1506) create event on environment_ids []
2020-12-08T02:00:06 [I|aud|] Katello::ContentView (11) update event on next_version 88, 89
2020-12-08T02:00:06 [I|aud|] Katello::ContentViewEnvironment (23) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on pulp_id 3-OracleLinux-8-v88_0-6de800b9-02e9-40df-9b07-1234775b6e60
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on library_instance_id 8733
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on content_view_version_id 1506
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/OracleLinux-8-x86_64-codeready-builder
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on environment_id
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on saved_checksum_type sha1
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on distribution_version
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on distribution_arch
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on distribution_bootable
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on distribution_family
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on distribution_variant
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on container_repository_name
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on root_id 48
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on remote_href
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on publication_href
2020-12-08T02:00:22 [I|aud|] Katello::Repository (12150) create event on version_href
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on pulp_id 3-OracleLinux-8-v88_0-8c33c2cf-ecb3-43b3-945c-ba2225119b05
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on library_instance_id 6676
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on content_view_version_id 1506
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/OracleLinux-8-x86_64-appstream
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on environment_id
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on saved_checksum_type sha1
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on distribution_version
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on distribution_arch
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on distribution_bootable
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on distribution_family
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on distribution_variant
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on container_repository_name
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on root_id 35
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on remote_href
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on publication_href
2020-12-08T02:00:39 [I|aud|] Katello::Repository (12151) create event on version_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on pulp_id 3-OracleLinux-8-v88_0-dd1fe716-8d1d-4d12-a34e-f9c19f2703ef
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on library_instance_id 6951
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on content_view_version_id 1506
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/EPEL-8-x86_64
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on environment_id
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on saved_checksum_type sha256
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on distribution_version
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on distribution_arch
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on distribution_bootable
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on distribution_family
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on distribution_variant
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on container_repository_name
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on root_id 41
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on remote_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on publication_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12152) create event on version_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on pulp_id 3-OracleLinux-8-v88_0-34d658b8-9188-4adc-8d17-cba89345c0db
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on library_instance_id 8984
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on content_view_version_id 1506
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/OracleLinux-8-x86_84-uek
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on environment_id
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on saved_checksum_type sha1
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on distribution_version
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on distribution_arch
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on distribution_bootable
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on distribution_family
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on distribution_variant
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on container_repository_name
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on root_id 49
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on remote_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on publication_href
2020-12-08T02:00:44 [I|aud|] Katello::Repository (12153) create event on version_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on pulp_id 3-OracleLinux-8-v88_0-faf16a89-2a91-4ec8-8fae-45f54db68d6d
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on library_instance_id 6675
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on content_view_version_id 1506
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/OracleLinux-8-x86_64-baseos
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on environment_id
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on saved_checksum_type sha1
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on distribution_version
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on distribution_arch
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on distribution_bootable
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on distribution_family
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on distribution_variant
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on container_repository_name
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on root_id 34
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on remote_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on publication_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12154) create event on version_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on pulp_id 3-OracleLinux-8-v88_0-58200606-a046-4847-83e8-5887be80ecd2
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on library_instance_id 11160
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on content_view_version_id 1506
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on relative_path My_Org/content_views/OracleLinux-8/88.0/custom/CentOS/Foreman-Client-2_1-EL8-x86_64
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on environment_id
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on saved_checksum_type sha256
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on distribution_version
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on distribution_arch
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on distribution_bootable
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on distribution_family
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on distribution_variant
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on container_repository_name
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on root_id 60
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on remote_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on publication_href
2020-12-08T02:00:49 [I|aud|] Katello::Repository (12155) create event on version_href
2020-12-08T02:00:50 [I|aud|] Katello::Repository (8738) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:50 [I|aud|] Katello::Repository (6678) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:50 [I|aud|] Katello::Repository (6968) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:50 [I|aud|] Katello::Repository (8994) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:50 [I|aud|] Katello::Repository (6680) update event on content_view_version_id 1501, 1506
2020-12-08T02:00:51 [I|aud|] Katello::Repository (11169) update event on content_view_version_id 1501, 1506
2020-12-08T02:11:57 [I|aud|] Katello::ContentViewVersion (1506) update event on content_counts , {"deb"=>0, "docker_manifest"=>0, "docker_manifest_list"=>0, "docker_tag"=>0, "file"=>0, "puppet_module"=>0, "rpm"=>32130, "modulemd"=>272, "erratum"=>4150, "package_group"=>78, "yum_repo_metadata_file"=>1, "srpm"=>6157}

OK, so I can’t believe I didn’t look at the Apache error log before now:

[Tue Dec 08 09:08:43.410597 2020] [proxy_http:error] [pid 110658] (70007)The timeout specified has expired: [client 10.10.10.10:48310] AH01102: error reading status line from remote server 127.0.0.1:3000
[Tue Dec 08 09:08:43.410669 2020] [proxy:error] [pid 110658] [client 10.10.10.10:48310] AH00898: Timeout on 100-Continue returned by /katello/api/content_views/11/publish

For this attempt the first log entry in production.log is 2020-12-08T09:08:13 and Apache times out at 09:08:43 - just 30 seconds later?

httpd/foreman-ssl_error_ssl.log:[Tue Dec 08 09:08:43.410597 2020] [proxy_http:error] [pid 110658] (70007)The timeout specified has expired: [client 10.10.10.10:48310] AH01102: error reading status line from remote server 127.0.0.1:3000
httpd/foreman-ssl_error_ssl.log:[Tue Dec 08 09:08:43.410669 2020] [proxy:error] [pid 110658] [client 10.10.10.10:48310] AH00898: Timeout on 100-Continue returned by /katello/api/content_views/11/publish
httpd/foreman-ssl_error_ssl.log-20201205.gz:[Fri Dec 04 04:26:36.003202 2020] [proxy:error] [pid 128780] (32)Broken pipe: [client 10.12.225.51:39064] AH01084: pass request body failed to 127.0.0.1:3000 (127.0.0.1)
httpd/foreman-ssl_error_ssl.log-20201205.gz:[Fri Dec 04 04:26:36.003255 2020] [proxy_http:error] [pid 128780] [client 10.12.225.51:39064] AH01097: pass request body failed to 127.0.0.1:3000 (127.0.0.1) from 10.12.225.51 ()
httpd/foreman-ssl_error_ssl.log-20201207.gz:[Sun Dec 06 23:00:50.366711 2020] [proxy_http:error] [pid 38888] (70007)The timeout specified has expired: [client 10.10.10.10:43642] AH01102: error reading status line from remote server 127.0.0.1:3000
httpd/foreman-ssl_error_ssl.log-20201207.gz:[Sun Dec 06 23:00:50.366766 2020] [proxy:error] [pid 38888] [client 10.10.10.10:43642] AH00898: Timeout on 100-Continue returned by /katello/api/v2/packages
httpd/foreman-ssl_error_ssl.log-20201207.gz:[Mon Dec 07 03:00:36.954039 2020] [proxy_http:error] [pid 96746] (70007)The timeout specified has expired: [client 10.10.10.10:37120] AH01102: error reading status line from remote server 127.0.0.1:3000
httpd/foreman-ssl_error_ssl.log-20201207.gz:[Mon Dec 07 03:00:36.954099 2020] [proxy:error] [pid 96746] [client 10.10.10.10:37120] AH00898: Timeout on 100-Continue returned by /katello/api/content_views/11/publish
httpd/foreman-ssl_error_ssl.log-20201208.gz:[Mon Dec 07 03:30:36.215098 2020] [proxy_http:error] [pid 119316] (70007)The timeout specified has expired: [client 10.10.10.10:59372] AH01102: error reading status line from remote server 127.0.0.1:3000
httpd/foreman-ssl_error_ssl.log-20201208.gz:[Mon Dec 07 03:30:36.215809 2020] [proxy:error] [pid 119316] [client 10.10.10.10:59372] AH00898: Timeout on 100-Continue returned by /katello/api/content_views/7/publish
httpd/foreman-ssl_error_ssl.log-20201208.gz:[Tue Dec 08 02:00:35.153018 2020] [proxy_http:error] [pid 15412] (70007)The timeout specified has expired: [client 10.10.10.10:38078] AH01102: error reading status line from remote server 127.0.0.1:3000
httpd/foreman-ssl_error_ssl.log-20201208.gz:[Tue Dec 08 02:00:35.153104 2020] [proxy:error] [pid 15412] [client 10.10.10.10:38078] AH00898: Timeout on 100-Continue returned by /katello/api/content_views/11/publish

Those apache logs are helpful. Mind trying another tweak in 05-foreman-ssl.conf?

Add within the <VirtualHost> definition:

SetEnv force-proxy-request-1.0 1
SetEnv proxy-nokeepalive 1

In conjunction with setting the ProxyPass back to its original state:

ProxyPass / http://127.0.0.1:3000/ retry=0 timeout=900

So, that looks more positive so far…interesting to note is that the original 05-foreman-ssl.conf actually read as below, presumably because the config file is templated with the server name, and then never replaced with new versions?

ProxyPass / http://127.0.0.1:3000/ retry=0

10.12.34.97 - - [08/Dec/2020:19:52:11 +0000] "POST /katello/api/content_views/11/publish HTTP/1.1" 202 1268 "-" "-"

# sudo -u apache DEBUG=main scl enable rh-nodejs10 -- node /opt/tools/katello-auto-publish/index.js -c OracleLinux-8
  main Skipping 'CentOS-6' +0ms
  main Skipping 'CentOS-7' +1ms
  main Publishing 'OracleLinux-8' with description '2020/12/08 [auto]' +1ms
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +1m
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +20s
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +20s
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +21s
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +20s
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +20s
  main Waiting for task 5b3c0b7e-a7df-474e-8e0c-54c6f256acc2 to finish... +20s

Looks like without the timeout value in the ProxyPass line the timeout would have defaulted to ‘Timeout’ default, of 60s.

Well, in fact:

# grep -rni timeout /etc/httpd
/etc/httpd/conf/httpd.conf:9:Timeout 60
/etc/httpd/conf/httpd.conf:12:KeepAliveTimeout 15
/etc/httpd/conf.d/pulp_streamer.conf:51:    ProxySet connectiontimeout=60
/etc/httpd/conf.d/05-foreman-ssl.conf:56:  ProxyPass / http://127.0.0.1:3000/ retry=0 timeout=900
/etc/httpd/conf.d/05-foreman-ssl.conf:57:#  ProxyPass / http://127.0.0.1:3000/ retry=0 keepalive=On ping=30 timeout=900
/etc/httpd/conf.d/ssl.conf:12:  SSLSessionCacheTimeout 300

The timeout=900 might be a new flag in Foreman 2.3 / Katello 3.18 !

Ah, interesting - as based on my script’s debug output the POST took “1m”, which is a little too rough to know whether that’s more or less than 60s…

By the way, looking forward to Pulp 3 - this is not pleasant to see for a simple content view version deletion:

Hey @John_Beranek how are things looking with that apache config in place for a few days now?

No more of those errors since the Apache config change. :+1:

1 Like

Thanks! If you notice that this starts happening again after you upgrade (which will remove the two SetEnv options we added) please let us know. However, I think it was adding the timeout=900 that fixed the issue based on the logs you shared. And that new configuration will be included in Katello 3.18

1 Like