RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1838012 - rhsmcertd will update the syspurpose to the Satellite/RHSM server on every certCheck even there is no change
Summary: rhsmcertd will update the syspurpose to the Satellite/RHSM server on every ce...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.8
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: rc
: ---
Assignee: candlepin-bugs
QA Contact: Red Hat subscription-manager QE Team
URL:
Whiteboard:
Depends On:
Blocks: 1855280
TreeView+ depends on / blocked
 
Reported: 2020-05-20 11:22 UTC by Hao Chang Yu
Modified: 2024-12-20 19:05 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1855280 (view as bug list)
Environment:
Last Closed: 2020-09-29 19:24:22 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github candlepin subscription-manager pull 2264 0 None closed 1838012: prevent redundant remote syspurpose sync 2021-02-19 02:06:54 UTC
Red Hat Product Errata RHBA-2020:3866 0 None None None 2020-09-29 19:24:30 UTC

Description Hao Chang Yu 2020-05-20 11:22:25 UTC 
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
Comment 2 Hao Chang Yu 2020-05-20 11:25:49 UTC 
Additional info

"subscription-manager status" command also sending the syspurpose update to the server every time even nothing has changed.
Comment 3 Pavel Moravec 2020-05-21 13:50:58 UTC 
(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 ?
Comment 4 Pavel Moravec 2020-05-21 13:54:27 UTC 
Btw RHEL8 is affected the same; the bug is in python-syspurpose / python3-syspurpose package.
Comment 5 Pavel Moravec 2020-05-21 14:16:26 UTC 
.. and the above patch fixes *both* rhsmcertd *and* "sub-man status" redundant calls of PUT the syspurpose data.
Comment 6 Hao Chang Yu 2020-05-22 08:50:01 UTC 
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
Comment 7 Hao Chang Yu 2020-05-22 08:53:16 UTC 
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.
Comment 9 William Poteat 2020-06-17 15:53:21 UTC 
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.
Comment 13 Craig Donnelly 2020-06-22 11:01:47 UTC 
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.
Comment 14 Craig Donnelly 2020-07-06 21:58:34 UTC 
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.
Comment 19 errata-xmlrpc 2020-09-29 19:24:22 UTC 
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
Note You need to log in before you can comment on or make changes to this bug.