Bug 1838012
| Summary: | rhsmcertd will update the syspurpose to the Satellite/RHSM server on every certCheck even there is no change | |||
|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Hao Chang Yu <hyu> | |
| Component: | subscription-manager | Assignee: | candlepin-bugs | |
| Status: | CLOSED ERRATA | QA Contact: | Red Hat subscription-manager QE Team <rhsm-qe> | |
| Severity: | high | Docs Contact: | ||
| Priority: | high | |||
| Version: | 7.8 | CC: | candlepin-bugs, cdonnell, jsefler, pmoravec, pvlasin, qianzhan, redakkan, rjerrido, wpoteat, yanpliu | |
| Target Milestone: | rc | Keywords: | Patch, Triaged, ZStream | |
| Target Release: | --- | |||
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | ||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | ||
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 1855280 (view as bug list) | Environment: | ||
| Last Closed: | 2020-09-29 19:24:22 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: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 1855280 | |||
Additional info "subscription-manager status" command also sending the syspurpose update to the server every time even nothing has changed. (In reply to Hao Chang Yu from comment #2) > Additional info > > "subscription-manager status" command also sending the syspurpose update to > the server every time even nothing has changed. Backtrace of this: File "/usr/sbin/subscription-manager", line 9, in <module> load_entry_point('subscription-manager==1.24.37', 'console_scripts', 'subscription-manager')() File "/usr/lib64/python2.7/site-packages/subscription_manager/scripts/subscription_manager.py", line 86, in main return managercli.ManagerCLI().main() File "/usr/lib64/python2.7/site-packages/subscription_manager/managercli.py", line 3041, in main ret = CLI.main(self) File "/usr/lib64/python2.7/site-packages/subscription_manager/cli.py", line 183, in main return cmd.main() File "/usr/lib64/python2.7/site-packages/subscription_manager/managercli.py", line 545, in main return_code = self._do_command() File "/usr/lib64/python2.7/site-packages/subscription_manager/managercli.py", line 3008, in _do_command store.sync() File "/usr/lib/python2.7/site-packages/syspurpose/files.py", line 291, in sync sync_result = SyncResult(result, self.update_remote(result), Relevant source code: remote_contents = self.get_remote_contents() local_contents = self.get_local_contents() cached_contents = self.get_cached_contents() result = self.merge(local=local_contents, remote=remote_contents, base=cached_contents) local_result = {key: result[key] for key in result if result[key]} sync_result = SyncResult(result, self.update_remote(result), <<<---- this line is called self.update_local(local_result), self.update_cache(result), self.report) the "self.update_remote(result)" is called even if remote_contents == cached_contents == result. That is redundant: why to update RHSM server if no change happened? Maybe a monkey patch like below can help? --- /usr/lib/python2.7/site-packages/syspurpose/files.py.orig 2020-05-21 15:43:53.476537004 +0200 +++ /usr/lib/python2.7/site-packages/syspurpose/files.py.new 2020-05-21 15:45:10.276448664 +0200 @@ -288,9 +288,11 @@ class SyncedStore(object): local_result = {key: result[key] for key in result if result[key]} - sync_result = SyncResult(result, self.update_remote(result), - self.update_local(local_result), - self.update_cache(result), self.report) + sync_result = SyncResult(result, + (remote_contents == result) or self.update_remote(result), + (local_contents == result) or self.update_local(local_result), + (cached_contents ==result) or self.update_cache(result), + self.report) log.debug('Successfully synced system purpose.') (or just the "(remote_contents == result) or self.update_remote(result)," change that is the only important for us). This change might alter SyncResult content in some rare use cases (uep cert missing or consumer_uuid is None) - but maybe in these use cases remote_contents != result ? Btw RHEL8 is affected the same; the bug is in python-syspurpose / python3-syspurpose package. .. and the above patch fixes *both* rhsmcertd *and* "sub-man status" redundant calls of PUT the syspurpose data. Actually it is not just subscription-manager status that will triggered the unneeded syspurpose PUT request. Any subscription-manager that runs ActionClient() will trigger it, such as identity, attach/remove etc Additionally, It is also 1 of the reason that could cause duplicate Katello::Hosts::Update tasks in the Satellite, e.g. facts upload follows by syspurpose update. 1. As this may be the last release of subscription-manager for RHEL 7, it needs to be in 7.9. We have customer issues for this bug where subscription-manager is sending call to the entitlement server unneccesarily. 2. This fix has already been verified in RHEL 8. We made a scratch build for RHEL 7.9 and ran it through a Tier1 test. It did not produce any regressions. It will not be a problem for the fix to be tested in our QE process. Verifying against RHEL 7.9 compose and subscription-manager-1.24.42-1: >> Reproducing issue: [root@dhcp-8-29-94 ~]# rpm -q subscription-manager subscription-manager-1.24.40-1.el7.x86_64 [root@dhcp-8-29-94 ~]# subscription-manager register --auto-attach Registering to: cragsat66.usersys.redhat.com:443/rhsm Username: admin Password: The system has been registered with ID: cada94f8-8559-403a-8fe5-51eb88161a25 The registered system name is: dhcp-8-29-94.lab.eng.rdu2.redhat.com Installed Product Current Status: Product Name: Red Hat Enterprise Linux for x86_64 High Touch Beta Status: Subscribed [root@dhcp-8-29-94 ~]# syspurpose set-role "Red Hat Enterprise Linux Server" role set to "Red Hat Enterprise Linux Server". > cmd to turn splay off, restart rhsmcertd, and tail log.. [root@dhcp-8-29-94 ~]# splay Mon Jun 22 06:12:28 2020 [INFO] Auto-attach interval: 1440.0 minutes [86400 seconds] Mon Jun 22 06:12:28 2020 [INFO] Cert check interval: 240.0 minutes [14400 seconds] Mon Jun 22 06:12:28 2020 [INFO] Waiting 2.0 minutes plus 32209 splay seconds [32329 seconds total] before performing first auto-attach. Mon Jun 22 06:12:28 2020 [INFO] Waiting 2.0 minutes plus 741 splay seconds [861 seconds total] before performing first cert check. Mon Jun 22 06:24:23 2020 [INFO] rhsmcertd is shutting down... Mon Jun 22 06:24:23 2020 [INFO] Starting rhsmcertd... Mon Jun 22 06:24:23 2020 [INFO] Auto-attach interval: 1440.0 minutes [86400 seconds] Mon Jun 22 06:24:23 2020 [INFO] Cert check interval: 240.0 minutes [14400 seconds] Mon Jun 22 06:24:23 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first auto-attach. Mon Jun 22 06:24:23 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first cert check. Mon Jun 22 06:26:25 2020 [INFO] (Cert Check) Certificates updated. Mon Jun 22 06:26:26 2020 [INFO] (Auto-attach) Certificates updated. >> Satellite: 2020-06-22T06:21:36 [I|app|a1b5c943] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:21:36 [I|app|a1b5c943] Parameters: {"usage"=>"", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:21:36 [I|app|a1b5c943] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) > Waiting for rhsmcertd checkin without changes.. 2020-06-22T06:26:26 [I|app|5f1d11ed] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:26:26 [I|app|5f1d11ed] Parameters: {"usage"=>"", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} >> Duplicate syspurpose upload without changes observed ^ >> Now trying new subman: >> Host: [root@dhcp-8-29-94 ~]# yum update subscription-manager Loaded plugins: product-id, search-disabled-repos, subscription-manager brew-task-repo-subscription-manager-1.24.42-1.el7 | 2.5 kB 00:00 brew-task-repo-subscription-manager-1.24.42-1.el7/x86_64/ | 9.4 kB 00:00 Resolving Dependencies --> Running transaction check ---> Package subscription-manager.x86_64 0:1.24.40-1.el7 will be updated ---> Package subscription-manager.x86_64 0:1.24.42-1.el7 will be an update --> Processing Dependency: subscription-manager-rhsm = 1.24.42 for package: subscription-manager-1.24.42-1.el7.x86_64 --> Running transaction check ---> Package subscription-manager-rhsm.x86_64 0:1.24.40-1.el7 will be updated ---> Package subscription-manager-rhsm.x86_64 0:1.24.42-1.el7 will be an update --> Processing Dependency: subscription-manager-rhsm-certificates = 1.24.42-1.el7 for package: subscription-manager-rhsm-1.24.42-1.el7.x86_64 --> Running transaction check ---> Package subscription-manager-rhsm-certificates.x86_64 0:1.24.40-1.el7 will be updated ---> Package subscription-manager-rhsm-certificates.x86_64 0:1.24.42-1.el7 will be an update --> Finished Dependency Resolution Dependencies Resolved =============================================================================== Package Arch Version Repository Size =============================================================================== Updating: subscription-manager x86_64 1.24.42-1.el7 brew-task-repo-subscription-manager-1.24.42-1.el7 1.1 M Updating for dependencies: subscription-manager-rhsm x86_64 1.24.42-1.el7 brew-task-repo-subscription-manager-1.24.42-1.el7 330 k subscription-manager-rhsm-certificates x86_64 1.24.42-1.el7 brew-task-repo-subscription-manager-1.24.42-1.el7 239 k Transaction Summary =============================================================================== Upgrade 1 Package (+2 Dependent packages) Total download size: 1.6 M Is this ok [y/d/N]: y Downloading packages: Delta RPMs disabled because /usr/bin/applydeltarpm not installed. (1/3): subscription-manager-rhsm-1.24.42-1.el7.x86_64.rpm | 330 kB 00:00 (2/3): subscription-manager-1.24.42-1.el7.x86_64.rpm | 1.1 MB 00:00 (3/3): subscription-manager-rhsm-certificates-1.24.42-1.e | 239 kB 00:00 ------------------------------------------------------------------------------- Total 2.1 MB/s | 1.6 MB 00:00 Running transaction check Running transaction test Transaction test succeeded Running transaction Warning: RPMDB altered outside of yum. Updating : subscription-manager-rhsm-certificates-1.24.42-1.el7.x86_ 1/6 Updating : subscription-manager-rhsm-1.24.42-1.el7.x86_64 2/6 Updating : subscription-manager-1.24.42-1.el7.x86_64 3/6 Cleanup : subscription-manager-1.24.40-1.el7.x86_64 4/6 Cleanup : subscription-manager-rhsm-1.24.40-1.el7.x86_64 5/6 Cleanup : subscription-manager-rhsm-certificates-1.24.40-1.el7.x86_ 6/6 Verifying : subscription-manager-rhsm-certificates-1.24.42-1.el7.x86_ 1/6 Verifying : subscription-manager-rhsm-1.24.42-1.el7.x86_64 2/6 Verifying : subscription-manager-1.24.42-1.el7.x86_64 3/6 Verifying : subscription-manager-rhsm-1.24.40-1.el7.x86_64 4/6 Verifying : subscription-manager-1.24.40-1.el7.x86_64 5/6 Verifying : subscription-manager-rhsm-certificates-1.24.40-1.el7.x86_ 6/6 Updated: subscription-manager.x86_64 0:1.24.42-1.el7 Dependency Updated: subscription-manager-rhsm.x86_64 0:1.24.42-1.el7 subscription-manager-rhsm-certificates.x86_64 0:1.24.42-1.el7 Complete! [root@dhcp-8-29-94 ~]# splay Mon Jun 22 06:30:26 2020 [INFO] Auto-attach interval: 1440.0 minutes [86400 seconds] Mon Jun 22 06:30:26 2020 [INFO] Cert check interval: 240.0 minutes [14400 seconds] Mon Jun 22 06:30:26 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first auto-attach. Mon Jun 22 06:30:26 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first cert check. Mon Jun 22 06:30:38 2020 [INFO] rhsmcertd is shutting down... Mon Jun 22 06:30:38 2020 [INFO] Starting rhsmcertd... Mon Jun 22 06:30:38 2020 [INFO] Auto-attach interval: 1440.0 minutes [86400 seconds] Mon Jun 22 06:30:38 2020 [INFO] Cert check interval: 240.0 minutes [14400 seconds] Mon Jun 22 06:30:38 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first auto-attach. Mon Jun 22 06:30:38 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first cert check. Mon Jun 22 06:32:39 2020 [INFO] (Cert Check) Certificates updated. Mon Jun 22 06:32:40 2020 [INFO] (Auto-attach) Certificates updated. >> Satellite: 10.8.29.94 - - [22/Jun/2020:06:32:38 -0400] "GET /rhsm/ HTTP/1.1" 200 2125 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:38 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials HTTP/1.1" 200 32 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:32:38 [I|app|56c48ab8] Started GET "/rhsm/" for 10.8.29.94 at 2020-06-22 06:32:38 -0400 2020-06-22T06:32:38 [I|app|56c48ab8] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON 2020-06-22T06:32:38 [I|app|56c48ab8] Parameters: {"root"=>{}} 2020-06-22T06:32:38 [I|app|56c48ab8] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection 2020-06-22T06:32:38 [I|app|56c48ab8] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (3.0ms) 2020-06-22T06:32:38 [I|app|56c48ab8] Completed 200 OK in 39ms (Views: 4.6ms | ActiveRecord: 11.3ms) 2020-06-22T06:32:38 [I|app|4667724b] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials" for 10.8.29.94 at 2020-06-22 06:32:38 -0400 2020-06-22T06:32:38 [I|app|4667724b] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON 2020-06-22T06:32:38 [I|app|4667724b] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:38 [I|app|4667724b] Completed 200 OK in 78ms (Views: 0.5ms | ActiveRecord: 10.7ms) ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:32:38 -0400] "GET /rhsm/status HTTP/1.1" 200 377 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:38 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19813 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:38 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/content_overrides HTTP/1.1" 200 2 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:39 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19813 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:39 -0400] "PUT /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 41 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:32:38 [I|app|6f0e1f3a] Started GET "/rhsm/status" for 10.8.29.94 at 2020-06-22 06:32:38 -0400 2020-06-22T06:32:38 [I|app|6f0e1f3a] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON 2020-06-22T06:32:38 [I|app|6f0e1f3a] Completed 200 OK in 25ms (Views: 0.6ms | ActiveRecord: 5.1ms) 2020-06-22T06:32:38 [I|app|9db40574] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:38 -0400 2020-06-22T06:32:38 [I|app|9db40574] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:32:38 [I|app|9db40574] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:38 [I|app|9db40574] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:38 [I|app|9db40574] Completed 200 OK in 77ms (Views: 6.1ms | ActiveRecord: 6.6ms) 2020-06-22T06:32:38 [I|app|84071800] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/content_overrides" for 10.8.29.94 at 2020-06-22 06:32:38 -0400 2020-06-22T06:32:38 [I|app|84071800] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON 2020-06-22T06:32:38 [I|app|84071800] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:38 [I|app|84071800] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:38 [I|app|84071800] Completed 200 OK in 33ms (Views: 0.2ms | ActiveRecord: 5.5ms) 2020-06-22T06:32:39 [I|app|59f75333] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:39 -0400 2020-06-22T06:32:39 [I|app|59f75333] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:32:39 [I|app|59f75333] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:39 [I|app|59f75333] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:39 [I|app|59f75333] Completed 200 OK in 78ms (Views: 7.6ms | ActiveRecord: 6.1ms) 2020-06-22T06:32:39 [I|app|f57121fa] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:39 -0400 2020-06-22T06:32:39 [I|app|f57121fa] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:32:39 [I|app|f57121fa] Parameters: {"usage"=>"", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:39 [I|app|f57121fa] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:39 [I|bac|f57121fa] Task {label: Actions::Katello::Host::Update, id: ea697868-0867-433d-b0c0-e5d33d4daa83, execution_plan_id: 092a0be1-2605-41c7-949d-446ff84df5fb} state changed: planning 2020-06-22T06:32:39 [I|bac|] Task {label: Actions::Katello::Host::Update, id: ea697868-0867-433d-b0c0-e5d33d4daa83, execution_plan_id: 092a0be1-2605-41c7-949d-446ff84df5fb} state changed: planned 2020-06-22T06:32:39 [I|app|] Completed 200 OK in 239ms (Views: 0.3ms | ActiveRecord: 45.3ms) ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:32:39 -0400] "GET /rhsm/ HTTP/1.1" 200 2125 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:39 -0400] "GET /rhsm/status HTTP/1.1" 200 377 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:39 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19813 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:40 -0400] "PUT /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 41 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:40 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19813 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:32:40 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/compliance HTTP/1.1" 200 4504 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:32:39 [I|app|86bf2166] Started GET "/rhsm/" for 10.8.29.94 at 2020-06-22 06:32:39 -0400 2020-06-22T06:32:39 [I|app|86bf2166] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON 2020-06-22T06:32:39 [I|app|86bf2166] Parameters: {"root"=>{}} 2020-06-22T06:32:39 [I|app|86bf2166] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection 2020-06-22T06:32:39 [I|app|86bf2166] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (2.0ms) 2020-06-22T06:32:39 [I|app|86bf2166] Completed 200 OK in 21ms (Views: 3.0ms | ActiveRecord: 4.7ms) 2020-06-22T06:32:39 [I|app|068c7ccd] Started GET "/rhsm/status" for 10.8.29.94 at 2020-06-22 06:32:39 -0400 2020-06-22T06:32:39 [I|app|068c7ccd] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON 2020-06-22T06:32:39 [I|app|068c7ccd] Completed 200 OK in 22ms (Views: 0.4ms | ActiveRecord: 4.2ms) 2020-06-22T06:32:39 [I|app|4b690a86] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:39 -0400 2020-06-22T06:32:39 [I|app|4b690a86] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:32:39 [I|app|4b690a86] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:40 [I|app|4b690a86] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:40 [I|app|4b690a86] Completed 200 OK in 89ms (Views: 7.8ms | ActiveRecord: 6.4ms) >> 2020-06-22T06:32:40 [I|app|1f658762] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:40 -0400 2020-06-22T06:32:40 [I|app|1f658762] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:32:40 [I|app|1f658762] Parameters: {"usage"=>"", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} >> Still a PUT for syspurpose updates? ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 2020-06-22T06:32:40 [I|app|1f658762] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:40 [I|bac|1f658762] Task {label: Actions::Katello::Host::Update, id: ca792031-1b6d-42d5-abb4-fd1ad1be5aa5, execution_plan_id: 5b725635-0461-481e-9970-68542d360763} state changed: planning 2020-06-22T06:32:40 [I|bac|] Task {label: Actions::Katello::Host::Update, id: ca792031-1b6d-42d5-abb4-fd1ad1be5aa5, execution_plan_id: 5b725635-0461-481e-9970-68542d360763} state changed: planned 2020-06-22T06:32:40 [I|app|] Completed 200 OK in 218ms (Views: 0.3ms | ActiveRecord: 35.9ms) 2020-06-22T06:32:40 [I|app|b9170546] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:32:40 -0400 2020-06-22T06:32:40 [I|app|b9170546] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:32:40 [I|app|b9170546] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:40 [I|app|b9170546] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:40 [I|app|b9170546] Completed 200 OK in 78ms (Views: 6.3ms | ActiveRecord: 6.1ms) 2020-06-22T06:32:40 [I|app|29e82cb2] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/compliance" for 10.8.29.94 at 2020-06-22 06:32:40 -0400 2020-06-22T06:32:40 [I|app|29e82cb2] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON 2020-06-22T06:32:40 [I|app|29e82cb2] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:32:40 [I|app|29e82cb2] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:32:40 [I|app|29e82cb2] Completed 200 OK in 57ms (Views: 0.2ms | ActiveRecord: 5.5ms) 2020-06-22T06:32:40 [I|app|bf72803c] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials" for 10.8.29.94 at 2020-06-22 06:32:40 -0400 2020-06-22T06:32:40 [I|app|bf72803c] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON 2020-06-22T06:32:40 [I|app|bf72803c] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:32:40 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials HTTP/1.1" 200 32 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:32:40 [I|app|bf72803c] Completed 200 OK in 52ms (Views: 0.3ms | ActiveRecord: 9.4ms) >> The Satellite section above indicates the full communication observed from foreman-tail for a single rhsmcertd checkin from this host, and there is still a PUT for syspurpose attributes that have not been touched. >> Double checking to confirm not a fluke, setting another attribute where we /expect/ an update: [root@dhcp-8-29-94 ~]# syspurpose set-usage Test usage set to "Test". >> Satellite full update from host: => /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:46:06 -0400] "GET /rhsm/status HTTP/1.1" 200 377 "-" "RHSM/1.0 (cmd=syspurpose)" 10.8.29.94 - - [22/Jun/2020:06:46:07 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19813 "-" "RHSM/1.0 (cmd=syspurpose)" 10.8.29.94 - - [22/Jun/2020:06:46:07 -0400] "PUT /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 41 "-" "RHSM/1.0 (cmd=syspurpose)" ==> /var/log/foreman/production.log <== 2020-06-22T06:46:06 [I|app|ae1772f1] Started GET "/rhsm/status" for 10.8.29.94 at 2020-06-22 06:46:06 -0400 2020-06-22T06:46:06 [I|app|ae1772f1] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON 2020-06-22T06:46:07 [I|app|ae1772f1] Completed 200 OK in 76ms (Views: 0.9ms | ActiveRecord: 15.4ms) 2020-06-22T06:46:07 [I|app|a256d146] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:46:07 -0400 2020-06-22T06:46:07 [I|app|a256d146] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:46:07 [I|app|a256d146] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:46:07 [I|app|a256d146] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:46:07 [I|app|a256d146] Completed 200 OK in 148ms (Views: 14.6ms | ActiveRecord: 10.1ms) >> 2020-06-22T06:46:07 [I|app|5e20f293] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:46:07 -0400 2020-06-22T06:46:07 [I|app|5e20f293] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:46:07 [I|app|5e20f293] Parameters: {"usage"=>"Test", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} >> We get our new usage updated here: ^^^^^^^^^^^^^^^^^^^^^^^^^ 2020-06-22T06:46:07 [I|app|5e20f293] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:46:07 [I|bac|5e20f293] Task {label: Actions::Katello::Host::Update, id: a3cd066b-4ebd-45b5-9e3a-d3a213edcbd8, execution_plan_id: e2b57678-78d7-4012-b12d-9069c2bf8728} state changed: planning 2020-06-22T06:46:07 [I|bac|] Task {label: Actions::Katello::Host::Update, id: a3cd066b-4ebd-45b5-9e3a-d3a213edcbd8, execution_plan_id: e2b57678-78d7-4012-b12d-9069c2bf8728} state changed: planned 2020-06-22T06:46:07 [I|app|] Completed 200 OK in 247ms (Views: 0.3ms | ActiveRecord: 47.5ms) >> Now restarting rhsmcertd on the host, and waiting for checkin: [root@dhcp-8-29-94 ~]# systemctl restart rhsmcertd;tail -f /var/log/rhsm/rhsmcertd.log Mon Jun 22 06:30:38 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first auto-attach. Mon Jun 22 06:30:38 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first cert check. Mon Jun 22 06:32:39 2020 [INFO] (Cert Check) Certificates updated. Mon Jun 22 06:32:40 2020 [INFO] (Auto-attach) Certificates updated. Mon Jun 22 06:48:18 2020 [INFO] rhsmcertd is shutting down... Mon Jun 22 06:48:18 2020 [INFO] Starting rhsmcertd... Mon Jun 22 06:48:18 2020 [INFO] Auto-attach interval: 1440.0 minutes [86400 seconds] Mon Jun 22 06:48:18 2020 [INFO] Cert check interval: 240.0 minutes [14400 seconds] Mon Jun 22 06:48:18 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first auto-attach. Mon Jun 22 06:48:18 2020 [INFO] Waiting 2.0 minutes plus 0 splay seconds [120 seconds total] before performing first cert check. Mon Jun 22 06:50:20 2020 [INFO] (Cert Check) Certificates updated. Mon Jun 22 06:50:21 2020 [INFO] (Auto-attach) Certificates updated. >> Full Satellite checkin, again updating unchanged syspurpose attributes via rhsmcertd: ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:50:18 -0400] "GET /rhsm/ HTTP/1.1" 200 2125 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:18 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials HTTP/1.1" 200 32 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:50:18 [I|app|f1eec445] Started GET "/rhsm/" for 10.8.29.94 at 2020-06-22 06:50:18 -0400 2020-06-22T06:50:18 [I|app|f1eec445] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON 2020-06-22T06:50:18 [I|app|f1eec445] Parameters: {"root"=>{}} 2020-06-22T06:50:18 [I|app|f1eec445] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection 2020-06-22T06:50:18 [I|app|f1eec445] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (4.3ms) 2020-06-22T06:50:18 [I|app|f1eec445] Completed 200 OK in 47ms (Views: 7.2ms | ActiveRecord: 6.0ms) 2020-06-22T06:50:18 [I|app|d54da3a4] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials" for 10.8.29.94 at 2020-06-22 06:50:18 -0400 2020-06-22T06:50:18 [I|app|d54da3a4] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON 2020-06-22T06:50:18 [I|app|d54da3a4] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:18 [I|app|d54da3a4] Completed 200 OK in 89ms (Views: 0.4ms | ActiveRecord: 11.4ms) ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:50:18 -0400] "GET /rhsm/status HTTP/1.1" 200 377 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:19 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19815 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:19 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/content_overrides HTTP/1.1" 200 2 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:50:18 [I|app|20152a44] Started GET "/rhsm/status" for 10.8.29.94 at 2020-06-22 06:50:18 -0400 2020-06-22T06:50:18 [I|app|20152a44] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON 2020-06-22T06:50:18 [I|app|20152a44] Completed 200 OK in 27ms (Views: 0.7ms | ActiveRecord: 4.5ms) 2020-06-22T06:50:19 [I|app|9330700a] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:19 -0400 2020-06-22T06:50:19 [I|app|9330700a] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:50:19 [I|app|9330700a] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:19 [I|app|9330700a] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:19 [I|app|9330700a] Completed 200 OK in 115ms (Views: 6.4ms | ActiveRecord: 7.2ms) 2020-06-22T06:50:19 [I|app|ebe2e6fb] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/content_overrides" for 10.8.29.94 at 2020-06-22 06:50:19 -0400 2020-06-22T06:50:19 [I|app|ebe2e6fb] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON 2020-06-22T06:50:19 [I|app|ebe2e6fb] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:19 [I|app|ebe2e6fb] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:19 [I|app|ebe2e6fb] Completed 200 OK in 35ms (Views: 0.2ms | ActiveRecord: 5.7ms) 2020-06-22T06:50:19 [I|app|265cb58f] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:19 -0400 ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:50:19 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19815 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:20 -0400] "PUT /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 41 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:20 -0400] "GET /rhsm/ HTTP/1.1" 200 2125 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:20 -0400] "GET /rhsm/status HTTP/1.1" 200 377 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:20 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19815 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:50:19 [I|app|265cb58f] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:50:19 [I|app|265cb58f] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:19 [I|app|265cb58f] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:20 [I|app|265cb58f] Completed 200 OK in 82ms (Views: 5.9ms | ActiveRecord: 7.3ms) >> 2020-06-22T06:50:20 [I|app|d1ffc537] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:20 -0400 2020-06-22T06:50:20 [I|app|d1ffc537] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:50:20 [I|app|d1ffc537] Parameters: {"usage"=>"Test", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} >>> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 2020-06-22T06:50:20 [I|app|d1ffc537] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:20 [I|bac|d1ffc537] Task {label: Actions::Katello::Host::Update, id: f4b02f2c-fc6f-4405-9c21-0c8e5e55927b, execution_plan_id: cc0f5343-0976-4fa7-9442-913456a31eb7} state changed: planning 2020-06-22T06:50:20 [I|bac|] Task {label: Actions::Katello::Host::Update, id: f4b02f2c-fc6f-4405-9c21-0c8e5e55927b, execution_plan_id: cc0f5343-0976-4fa7-9442-913456a31eb7} state changed: planned 2020-06-22T06:50:20 [I|app|] Completed 200 OK in 227ms (Views: 0.3ms | ActiveRecord: 40.5ms) 2020-06-22T06:50:20 [I|app|125821cc] Started GET "/rhsm/" for 10.8.29.94 at 2020-06-22 06:50:20 -0400 2020-06-22T06:50:20 [I|app|125821cc] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON 2020-06-22T06:50:20 [I|app|125821cc] Parameters: {"root"=>{}} 2020-06-22T06:50:20 [I|app|125821cc] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection 2020-06-22T06:50:20 [I|app|125821cc] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.12.0.27/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (2.3ms) 2020-06-22T06:50:20 [I|app|125821cc] Completed 200 OK in 21ms (Views: 3.3ms | ActiveRecord: 4.1ms) 2020-06-22T06:50:20 [I|app|24f0ba5b] Started GET "/rhsm/status" for 10.8.29.94 at 2020-06-22 06:50:20 -0400 2020-06-22T06:50:20 [I|app|24f0ba5b] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON 2020-06-22T06:50:20 [I|app|24f0ba5b] Completed 200 OK in 24ms (Views: 0.5ms | ActiveRecord: 4.2ms) 2020-06-22T06:50:20 [I|app|15e3dc8d] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:20 -0400 2020-06-22T06:50:20 [I|app|15e3dc8d] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:50:20 [I|app|15e3dc8d] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:20 [I|app|15e3dc8d] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:20 [I|app|15e3dc8d] Completed 200 OK in 79ms (Views: 6.0ms | ActiveRecord: 7.1ms) 2020-06-22T06:50:20 [I|app|182fbaae] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:20 -0400 2020-06-22T06:50:20 [I|app|182fbaae] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:50:20 [I|app|182fbaae] Parameters: {"usage"=>"Test", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:20 [I|app|182fbaae] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) ==> /var/log/httpd/foreman-ssl_access_ssl.log <== 10.8.29.94 - - [22/Jun/2020:06:50:20 -0400] "PUT /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 41 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:21 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25 HTTP/1.1" 200 19815 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:21 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/compliance HTTP/1.1" 200 4504 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" 10.8.29.94 - - [22/Jun/2020:06:50:21 -0400] "GET /rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials HTTP/1.1" 200 32 "-" "RHSM/1.0 (cmd=rhsmcertd-worker)" ==> /var/log/foreman/production.log <== 2020-06-22T06:50:20 [I|bac|182fbaae] Task {label: Actions::Katello::Host::Update, id: 10644ff3-8633-42f2-818f-2c8f3aad9ba5, execution_plan_id: e837048d-a72d-459e-959f-0caf12882d2e} state changed: planning 2020-06-22T06:50:21 [I|bac|] Task {label: Actions::Katello::Host::Update, id: 10644ff3-8633-42f2-818f-2c8f3aad9ba5, execution_plan_id: e837048d-a72d-459e-959f-0caf12882d2e} state changed: planned 2020-06-22T06:50:21 [I|app|] Completed 200 OK in 211ms (Views: 0.3ms | ActiveRecord: 38.5ms) 2020-06-22T06:50:21 [I|app|4d8714e2] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:50:21 -0400 2020-06-22T06:50:21 [I|app|4d8714e2] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-06-22T06:50:21 [I|app|4d8714e2] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:21 [I|app|4d8714e2] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:21 [I|app|4d8714e2] Completed 200 OK in 82ms (Views: 5.7ms | ActiveRecord: 6.9ms) 2020-06-22T06:50:21 [I|app|ac6ab9d5] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/compliance" for 10.8.29.94 at 2020-06-22 06:50:21 -0400 2020-06-22T06:50:21 [I|app|ac6ab9d5] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON 2020-06-22T06:50:21 [I|app|ac6ab9d5] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:21 [I|app|ac6ab9d5] Current user set to cada94f8-8559-403a-8fe5-51eb88161a25 (regular) 2020-06-22T06:50:21 [I|app|ac6ab9d5] Completed 200 OK in 54ms (Views: 0.2ms | ActiveRecord: 5.1ms) 2020-06-22T06:50:21 [I|app|80c402ca] Started GET "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25/certificates/serials" for 10.8.29.94 at 2020-06-22 06:50:21 -0400 2020-06-22T06:50:21 [I|app|80c402ca] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON 2020-06-22T06:50:21 [I|app|80c402ca] Parameters: {"id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} 2020-06-22T06:50:21 [I|app|80c402ca] Completed 200 OK in 75ms (Views: 0.3ms | ActiveRecord: 11.7ms) >> Testing other cmds that were supposed to be updated to prevent this: [root@dhcp-8-29-94 ~]# subscription-manager status +-------------------------------------------+ System Status Details +-------------------------------------------+ Overall Status: Current System Purpose Status: Mismatched - unsatisfied usage: Test - unsatisfied role: Red Hat Enterprise Linux Server ======================= 2020-06-22T06:54:29 [I|app|e7accdf4] Started PUT "/rhsm/consumers/cada94f8-8559-403a-8fe5-51eb88161a25" for 10.8.29.94 at 2020-06-22 06:54:29 -0400 2020-06-22T06:54:29 [I|app|e7accdf4] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-06-22T06:54:29 [I|app|e7accdf4] Parameters: {"usage"=>"Test", "addOns"=>[], "role"=>"Red Hat Enterprise Linux Server", "serviceLevel"=>"", "id"=>"cada94f8-8559-403a-8fe5-51eb88161a25"} ======================= [root@dhcp-8-29-94 ~]# subscription-manager identity system identity: cada94f8-8559-403a-8fe5-51eb88161a25 name: dhcp-8-29-94.lab.eng.rdu2.redhat.com org name: Red Hat org ID: Red_Hat environment name: Library ======================= >> This one did not trigger a PUT for syspurpose attrs. [root@dhcp-8-29-94 ~]# subscription-manager list +-------------------------------------------+ Installed Product Status +-------------------------------------------+ Product Name: Red Hat Enterprise Linux for x86_64 High Touch Beta Product ID: 230 Version: 7.9 HTB Arch: x86_64 Status: Subscribed Status Details: Starts: 10/24/2019 Ends: 10/23/2020 ====================== >> This one didn't either. Failed QA. Verification above failed because of a missing package update on the test system. >> python-syspurpose is not required to be updated along with subscription-manager at this point, and this is where the changes were made - causing me to miss the updates. A new BZ will be filed for updating this requirement within the RHEL 8 timeframe. Testing with python-syspurpose-1.24.42-1.el7.x86_64: >> RHEL System [root@dhcp-13-226-246 rhsm]# syspurpose set-role "RHEL Server Test" role set to "RHEL Server Test". >> Sat: 2020-07-06T17:29:25 [I|app|4522cea5] Started PUT "/rhsm/consumers/13ec98cf-269f-4655-b13d-548d9c864638" for 10.13.226.246 at 2020-07-06 17:29:25 -0400 2020-07-06T17:29:25 [I|app|4522cea5] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON 2020-07-06T17:29:25 [I|app|4522cea5] Parameters: {"usage"=>"", "addOns"=>[], "role"=>"RHEL Server Test", "serviceLevel"=>"", "id"=>"13ec98cf-269f-4655-b13d-548d9c864638"} >> RHEL System [root@dhcp-13-226-246 rhsm]# systemctl restart rhsmcertd;tail -f /var/log/rhsm/*.log <SNIP> 2020-07-06 17:38:21,009 [DEBUG] rhsmcertd-worker:20402:MainThread @files.py:351 - Successfully read remote syspurpose from server. 2020-07-06 17:38:21,009 [DEBUG] rhsmcertd-worker:20402:MainThread @files.py:555 - Attempting a three-way merge... 2020-07-06 17:38:21,010 [DEBUG] rhsmcertd-worker:20402:MainThread @files.py:509 - Successfully updated syspurpose values at '/etc/rhsm/syspurpose/syspurpose.json'. 2020-07-06 17:38:21,011 [DEBUG] rhsmcertd-worker:20402:MainThread @files.py:509 - Successfully updated syspurpose values at '/var/lib/rhsm/cache/syspurpose.json'. 2020-07-06 17:38:21,011 [DEBUG] rhsmcertd-worker:20402:MainThread @files.py:299 - Successfully synced system purpose. 2020-07-06 17:38:21,011 [DEBUG] rhsmcertd-worker:20402:MainThread @syspurposelib.py:215 - Syspurpose updated: Syspurpose Sync status: Successfully synced system purpose updates: exceptions: >> No PUT here, just some misleading messaging. >> Satellite: 2020-07-06T17:38:20 [I|app|1e529e22] Started GET "/rhsm/consumers/13ec98cf-269f-4655-b13d-548d9c864638" for 10.13.226.246 at 2020-07-06 17:38:20 -0400 2020-07-06T17:38:20 [I|app|1e529e22] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON 2020-07-06T17:38:20 [I|app|1e529e22] Parameters: {"id"=>"13ec98cf-269f-4655-b13d-548d9c864638"} 2020-07-06T17:38:20 [I|app|1e529e22] Current user set to 13ec98cf-269f-4655-b13d-548d9c864638 (regular) 2020-07-06T17:38:20 [I|app|1e529e22] Completed 200 OK in 84ms (Views: 7.6ms | ActiveRecord: 6.8ms) >> A GET for consumer data, but no PUTs recorded for syspurpose data for this host. The same follows through for `syspurpose show` and `subscription-manager status`. Updating syspurpose still works correctly when setting from client or from Satellite. Client updates will immediately PUT to satellite, satellite updates will pull with rhsmcertd checkin. Primary case for rhsmcertd checkins: VERIFIED. 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 (subscription-manager bug fix update), 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/RHBA-2020:3866 |
Description of problem: rhsmcertd will update the syspurpose to the Satellite/RHSM server on every certCheck even there is no change. This issue is causing performance issue to the Satellite server that managing thousands of hosts. Each unnecessary syspurpose update will create a task in the Satellite and Candlepin. Candlepin will also trigger event message to the Qpid broker causing Satellite to busy processing the messages. Steps to Reproduce: 1. To make it easier to reproduce, change the certCheckInterval in /etc/rhsm/rhsm.conf to 1 minute 2. systemctl restart rhsmcertd 3. On the Satellite tail the foreman production.log and wait for about 1 min tail -f /var/log/foreman/production.log Actual results: Seeing the following PUT request every minute even though syspurpose is not set or changed Started PUT "/rhsm/consumers/xxxx-xxxx-xxxx-xxxx" for xx.xx.xx.xx at 2020-05-20 11:13:18 +0000 Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON Parameters: {"usage"=>"", "addOns"=>[], "role"=>"", "serviceLevel"=>"", "id"=>"xxxx-xxxx-xxxx-xxxx"} Imagine that Satellite is managing 10K of hosts, each will run the certCheck every 4 hours, then Satellite will need to handle about 42 of this PUT request every minute. Expected results: Only send the PUT request if the local data is changed