Should I use foreman-debug -u ?

Yep, that works. Just provide the filename afterwards. Thanks!

Justin Sherrill wrote:

Yep, that works. Just provide the filename afterwards. Thanks!

Is there any specific log file you would like to check? This is our prod system with sensitive data. I am not sure I want to publish it without redacting it first.

Mainly the log files in /var/log/foreman-installer/

Before I gather log files, I did some test to make sure that client is actually sending facts. So I did subscription-manager facts --update, and here is client's rhsm.log:

2016-09-28 12:52:22,955 [DEBUG] subscription-manager:42346 @ga_loader.py:89 - ga_loader GaImporterGtk3
2016-09-28 12:52:22,957 [DEBUG] subscription-manager:42346 @plugins.py:569 - loaded plugin modules: []
2016-09-28 12:52:22,958 [DEBUG] subscription-manager:42346 @plugins.py:570 - loaded plugins: {}
2016-09-28 12:52:22,958 [DEBUG] subscription-manager:42346 @identity.py:131 - Loading consumer info from identity certificates.
2016-09-28 12:53:41,478 [DEBUG] subscription-manager:42364 @ga_loader.py:89 - ga_loader GaImporterGtk3
2016-09-28 12:53:41,481 [DEBUG] subscription-manager:42364 @plugins.py:569 - loaded plugin modules: []
2016-09-28 12:53:41,481 [DEBUG] subscription-manager:42364 @plugins.py:570 - loaded plugins: {}
2016-09-28 12:53:41,481 [DEBUG] subscription-manager:42364 @identity.py:131 - Loading consumer info from identity certificates.
2016-09-28 12:53:41,509 [INFO] subscription-manager:42364 @managercli.py:352 - Client Versions: {'python-rhsm': '1.15.4-5.el7', 'subscription-manager': '1.15.9-15.el7'}
2016-09-28 12:53:41,509 [INFO] subscription-manager:42364 @connection.py:778 - Connection built: host=katello.local port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-28 12:53:41,509 [INFO] subscription-manager:42364 @connection.py:778 - Connection built: host=katello.local port=443 handler=/rhsm auth=none
2016-09-28 12:53:41,527 [DEBUG] subscription-manager:42364 @connection.py:475 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, katello-server-ca.pem, katello-default-ca.pem
2016-09-28 12:53:41,527 [DEBUG] subscription-manager:42364 @connection.py:523 - Making request: GET /rhsm/
2016-09-28 12:53:41,585 [DEBUG] subscription-manager:42364 @connection.py:555 - Response: status=200
2016-09-28 12:53:41,586 [DEBUG] subscription-manager:42364 @connection.py:795 - Server supports the following resources: {'available_releases': '/rhsm/consumers/:id/available_releases', 'status': '/rhsm/status', 'guestids': '/rhsm/consumers/:id/guestids', 'content_overrides': '/rhsm/consumers/:id/content_overrides', 'environments': '/rhsm/owners/:organization_id/environments', 'hypervisors': '/rhsm/hypervisors', 'export': '/rhsm/consumers/:id/export', 'owner': '/rhsm/consumers/:id/owner', 'certificates': '/rhsm/consumers/:consumer_id/certificates', 'servicelevels': '/rhsm/owners/:organization_id/servicelevels', 'serials': '/rhsm/consumers/:id/certificates/serials', 'deleted_consumers': '/rhsm/deleted_consumers', 'consumers': '/rhsm/environments/:environment_id/consumers', 'entitlements': '/rhsm/entitlements', 'profile': '/rhsm/consumers/:id/profile', 'dry-run': '/rhsm/consumers/:id/entitlements/dry-run', 'subscriptions': '/rhsm/subscriptions', 'checkin': '/rhsm/consumers/:id/checkin', 'deletionrecord': '/rhsm/consumers/:id/deletionrecord', 'release': '/rhsm/consumers/:id/release', 'packages': '/rhsm/consumers/:id/packages', 'owners': '/rhsm/users/:login/owners', 'compliance': '/rhsm/consumers/:id/compliance', 'enabled_repos': '/rhsm/systems/:id/enabled_repos', 'pools': '/rhsm/pools'}
2016-09-28 12:53:41,587 [DEBUG] subscription-manager:42364 @connection.py:475 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, katello-server-ca.pem, katello-default-ca.pem
2016-09-28 12:53:41,587 [DEBUG] subscription-manager:42364 @connection.py:523 - Making request: GET /rhsm/status
2016-09-28 12:53:41,796 [DEBUG] subscription-manager:42364 @connection.py:555 - Response: status=200
2016-09-28 12:53:41,797 [INFO] subscription-manager:42364 @managercli.py:363 - Server Versions: {'rules-version': '5.15.2', 'candlepin': '3.1.0.1-Unknown', 'server-type': 'Red Hat Subscription Management'}
2016-09-28 12:53:41,797 [INFO] subscription-manager:42364 @managercli.py:328 - Consumer Identity name=vmnode.local uuid=5e26ff90-9d57-4b14-a256-fbffd0044ea4
2016-09-28 12:53:41,797 [DEBUG] subscription-manager:42364 @cache.py:138 - Checking current system info against cache: /var/lib/rhsm/facts/facts.json
2016-09-28 12:53:41,798 [DEBUG] subscription-manager:42364 @facts.py:73 - Cache /var/lib/rhsm/facts/facts.json does not exit
2016-09-28 12:53:41,798 [DEBUG] subscription-manager:42364 @cache.py:140 - System data has changed, updating server.
2016-09-28 12:53:41,798 [DEBUG] subscription-manager:42364 @facts.py:153 - Updating facts on server
2016-09-28 12:53:41,814 [DEBUG] subscription-manager:42364 @hwprobe.py:554 - cpu info: {'cpu.cpu(s)': 2, 'cpu.core(s)_per_socket': 1, 'cpu.thread(s)_per_core': 1, 'cpu.topology_source': 'kernel /sys cpu sibling lists', 'cpu.cpu_socket(s)': 2}
2016-09-28 12:54:06,839 [DEBUG] subscription-manager:42364 @hwprobe.py:772 - Running 'virt-what'
2016-09-28 12:54:06,879 [DEBUG] subscription-manager:42364 @hwprobe.py:776 - virt-what stdout: vmware

2016-09-28 12:54:06,879 [DEBUG] subscription-manager:42364 @hwprobe.py:777 - virt-what stderr:
2016-09-28 12:54:06,961 [INFO] subscription-manager:42364 @hwprobe.py:854 - collected virt facts: virt.is_guest=True, virt.host_type=vmware, virt.uuid=423febf5-d155-51ff-3634-d711f9f8a9f2
2016-09-28 12:54:06,963 [DEBUG] subscription-manager:42364 @connection.py:475 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, katello-server-ca.pem, katello-default-ca.pem
2016-09-28 12:54:06,963 [DEBUG] subscription-manager:42364 @connection.py:523 - Making request: PUT /rhsm/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4
2016-09-28 12:54:08,060 [DEBUG] subscription-manager:42364 @connection.py:555 - Response: status=200
2016-09-28 12:54:08,061 [DEBUG] subscription-manager:42364 @cache.py:110 - Wrote cache: /var/lib/rhsm/facts/facts.json
2016-09-28 12:54:08,061 [INFO] subscription-manager:42364 @managercli.py:1744 - Succesfully updated the system facts.

And if I open https://katello.local/rhsm/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4 I can see all the facts!

Very strange. Are you seeing any errors in your javascript console in the browser when you are on that content host details page? Also if you go to Hosts > All Hosts, click on the host, and then click 'facts' do you see them there?

This is production.log on Katello when I do subscription-manager facts --update on client:

2016-09-28 15:02:25 [app] [I] Started GET "/rhsm/" for 172.xx.xx.xx at 2016-09-28 15:02:25 +0200
2016-09-28 15:02:25 [app] [I] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2016-09-28 15:02:25 [app] [I] Parameters: {"root"=>{}}
2016-09-28 15:02:25 [app] [I] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.1.0.1/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (1.9ms)
2016-09-28 15:02:25 [app] [I] Completed 200 OK in 14ms (Views: 3.1ms | ActiveRecord: 0.0ms)
2016-09-28 15:02:25 [app] [I] Started GET "/rhsm/status" for 172.xx.xx.xx at 2016-09-28 15:02:25 +0200
2016-09-28 15:02:25 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2016-09-28 15:02:25 [app] [I] Completed 200 OK in 184ms (Views: 0.5ms | ActiveRecord: 0.0ms)
2016-09-28 15:02:51 [app] [I] Started PUT "/rhsm/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4" for 172.xx.xx.xx at 2016-09-28 15:02:51 +0200
2016-09-28 15:02:51 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON
2016-09-28 15:02:51 [app] [I] Parameters: {"facts"=>"[FILTERED]", "id"=>"5e26ff90-9d57-4b14-a256-fbffd0044ea4"}
2016-09-28 15:02:52 [app] [I] Completed 200 OK in 1163ms (Views: 0.4ms | ActiveRecord: 386.5ms)

And here is candlepin.log

2016-09-28 15:17:54,347 [thread=http-bio-8443-exec-3] [req=26d67f00-37ea-4661-9455-17e225895c38, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:17:54,349 [thread=http-bio-8443-exec-3] [req=26d67f00-37ea-4661-9455-17e225895c38, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=2
2016-09-28 15:17:54,383 [thread=http-bio-8443-exec-5] [req=debe8e01-5444-4bc2-be3d-3966510db8c5, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:17:54,384 [thread=http-bio-8443-exec-5] [req=debe8e01-5444-4bc2-be3d-3966510db8c5, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1
2016-09-28 15:17:54,417 [thread=http-bio-8443-exec-9] [req=ecedbac1-3db0-4626-8244-c8044c3a7a1a, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:17:54,418 [thread=http-bio-8443-exec-9] [req=ecedbac1-3db0-4626-8244-c8044c3a7a1a, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1
2016-09-28 15:17:54,458 [thread=http-bio-8443-exec-8] [req=a96fdbc5-387b-4e80-a86f-6ffe8eac8b77, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:17:54,459 [thread=http-bio-8443-exec-8] [req=a96fdbc5-387b-4e80-a86f-6ffe8eac8b77, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1
2016-09-28 15:17:54,494 [thread=http-bio-8443-exec-1] [req=d1eba577-913b-4360-921f-0e06edcf233a, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:17:54,495 [thread=http-bio-8443-exec-1] [req=d1eba577-913b-4360-921f-0e06edcf233a, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1

2016-09-28 15:18:20,059 [thread=http-bio-8443-exec-10] [req=3c464964-3844-4323-891d-8670261aa721, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:18:20,060 [thread=http-bio-8443-exec-10] [req=3c464964-3844-4323-891d-8670261aa721, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1
2016-09-28 15:18:20,095 [thread=http-bio-8443-exec-4] [req=c83477a1-251c-45a2-ae84-b80b1240c4eb, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2016-09-28 15:18:20,096 [thread=http-bio-8443-exec-4] [req=c83477a1-251c-45a2-ae84-b80b1240c4eb, org=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1
2016-09-28 15:18:20,293 [thread=http-bio-8443-exec-7] [req=8e2187d4-b07e-47fc-8b88-4c1add73212a, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=PUT, uri=/candlepin/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4
2016-09-28 15:18:20,333 [thread=http-bio-8443-exec-7] [req=8e2187d4-b07e-47fc-8b88-4c1add73212a, org=XXX] INFO org.candlepin.resource.ConsumerResource - Updating facts.
2016-09-28 15:18:20,422 [thread=http-bio-8443-exec-7] [req=8e2187d4-b07e-47fc-8b88-4c1add73212a, org=XXX] INFO org.candlepin.audit.HornetqEventDispatcher - Sending event: Event [id=null, target=COMPLIANCE, type=CREATED, time=Wed Sep 28 15:18:20 CEST 2016, entity=2c96481256f9d1cd0156fa4d5694012c]
2016-09-28 15:18:20,435 [thread=http-bio-8443-exec-7] [req=8e2187d4-b07e-47fc-8b88-4c1add73212a, org=XXX] INFO org.candlepin.audit.HornetqEventDispatcher - Sending event: Event [id=null, target=CONSUMER, type=MODIFIED, time=Wed Sep 28 15:18:20 CEST 2016, entity=2c96481256f9d1cd0156fa4d5694012c]
2016-09-28 15:18:20,437 [thread=http-bio-8443-exec-7] [req=8e2187d4-b07e-47fc-8b88-4c1add73212a, org=XXX] INFO org.candlepin.common.filter.LoggingFilter - Response: status=204, content-type="null", time=144
2016-09-28 15:18:20,483 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4/entitlements
2016-09-28 15:18:20,513 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.resource.ConsumerResource - Checked if consumer has unaccepted subscription terms in 0ms
2016-09-28 15:18:20,544 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.controller.Entitler - Attempting to heal host machine with UUID 653dac0a-9876-435c-9804-f2522bbd71ca for guest with UUID 5e26ff90-9d57-4b14-a256-fbffd0044ea4
2016-09-28 15:18:20,654 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.policy.js.autobind.AutobindRules - No pools available to rules for products: []
2016-09-28 15:18:20,654 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.controller.CandlepinPoolManager - No entitlements for host: 653dac0a-9876-435c-9804-f2522bbd71ca
2016-09-28 15:18:20,696 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.policy.js.autobind.AutobindRules - No pools available to rules for products: [2c96481256f9d1cd0156fa4d5694012d]
2016-09-28 15:18:20,696 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.controller.CandlepinPoolManager - No entitlements available for products: [2c96481256f9d1cd0156fa4d5694012d]
2016-09-28 15:18:20,698 [thread=http-bio-8443-exec-6] [req=d6d77723-2a17-4416-aeea-257ca6183c11, org=XXX] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=215

Hi Edgar,

I am still a bit perplexed by this. Could you tail -f /var/log/foreman/production.log and run the "subscription-manager facts --update" command and provide the produced logs?

Hi Justin

I already did that and posted results, check my comment #11 http://projects.theforeman.org/issues/16546#note-11

Would you like me to do that again?

Edgars

Ok, I did it again, here is the output from production.log:

2016-11-07 09:54:25 [app] [I] Started GET "/rhsm/consumers/5c281211-5e5e-4b90-8cf0-6af521f621c9" for 172.xx.xx.xx at 2016-11-07 09:54:25 +0100
2016-11-07 09:54:25 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON
2016-11-07 09:54:25 [app] [I] Parameters: {"id"=>"5c281211-5e5e-4b90-8cf0-6af521f621c9"}
2016-11-07 09:54:25 [app] [I] Completed 200 OK in 107ms (Views: 5.3ms | ActiveRecord: 1.4ms)
2016-11-07 09:54:25 [app] [I] Started PUT "/rhsm/consumers/5e26ff90-9d57-4b14-a256-fbffd0044ea4" for 172.xx.xx.xx at 2016-11-07 09:54:25 +0100
2016-11-07 09:54:25 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON
2016-11-07 09:54:25 [app] [I] Parameters: {"facts"=>"[FILTERED]", "id"=>"5e26ff90-9d57-4b14-a256-fbffd0044ea4"}
2016-11-07 09:54:27 [app] [I] Completed 200 OK in 1767ms (Views: 1.6ms | ActiveRecord: 754.2ms)
2016-11-07 09:54:27 [app] [I] Started GET "/rhsm/consumers/5c281211-5e5e-4b90-8cf0-6af521f621c9/compliance" for 172.xx.xx.xx at 2016-11-07 09:54:27 +0100
2016-11-07 09:54:27 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2016-11-07 09:54:27 [app] [I] Parameters: {"id"=>"5c281211-5e5e-4b90-8cf0-6af521f621c9"}
2016-11-07 09:54:27 [app] [I] Completed 200 OK in 87ms (Views: 0.3ms | ActiveRecord: 0.2ms)
2016-11-07 09:54:27 [app] [I] Started GET "/rhsm/consumers/5c281211-5e5e-4b90-8cf0-6af521f621c9/certificates/serials" for 172.xx.xx.xx at 2016-11-07 09:54:27 +0100
2016-11-07 09:54:27 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2016-11-07 09:54:27 [app] [I] Parameters: {"id"=>"5c281211-5e5e-4b90-8cf0-6af521f621c9"}
2016-11-07 09:54:27 [app] [I] Completed 200 OK in 112ms (Views: 0.4ms | ActiveRecord: 1.4ms)

That is really strange, here is what i get:

2016-11-07 08:28:16 cabf590b [app] [I] Started PUT "/rhsm/consumers/136b6c00-ce2a-47b2-a9cb-1c2abcb32343" for 127.0.0.1 at 2016-11-07 08:28:16 -0500
2016-11-07 08:28:16 cabf590b [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON
2016-11-07 08:28:16 cabf590b [app] [I]   Parameters: {"facts"=>"[FILTERED]", "id"=>"136b6c00-ce2a-47b2-a9cb-1c2abcb32343"}
2016-11-07 08:28:18 cabf590b [audit] [I] [centos7-katello-3-2.example.com] deleted 23 (6.3ms)
2016-11-07 08:28:18 cabf590b [audit] [I] [centos7-katello-3-2.example.com] updated 9 (108.7ms)
2016-11-07 08:28:19 cabf590b [audit] [I] [centos7-katello-3-2.example.com] added 0 (2.1ms)
2016-11-07 08:28:19 cabf590b [app] [I] Import facts for 'centos7-katello-3-2.example.com' completed. Added: 0, Updated: 9, Deleted 23 facts
2016-11-07 08:28:19 cabf590b [app] [I] Completed 200 OK in 3119ms (Views: 0.5ms | ActiveRecord: 331.0ms)

As you can see it processes the facts. Do you have the "create_new_host_when_facts_are_uploaded" setting set by chance? This is a foreman setting that prevents facts from being imported.

 hammer -u admin -p changeme settings list | grep create_new_host_when_facts_are_uploaded

I should clarify, that setting should be set to 'true' (the default). If it is set to false, no facts would be imported.

Yes, I have set this setting to false, because otherwise Puppet or Ansible will create hosts in Katello which are not subscribed to Katello. And I don't want that. This worked fine in previous versions, did anything change?

What changed is that Katello is now importing subscription-manager facts via foreman's infrastructure and code. To me I think this is a bug in foreman, as that setting indicates that it should still import the facts on a host that already exists. I'll chat with some foreman devs and see if i can fix that. Hopefully will have a patch for you soon :)

ok, thanks. I believe you can close this issue. After enabling this setting, I can see facts again.