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:
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.
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.
# 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.
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
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?
# 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
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âŚ
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