Issue with chef client uploading facts to foreman

andrp · April 2, 2019, 12:35pm

Hi,

I am testing foreman and trying to get it to work with chef (chef server version is 11.12)

Problem:
no chef facts / reports uploaded to foreman
chef-client runs ok on the node, but foreman displays the following error:

2019-04-02T12:06:14 [W|app|4470d5d5] Action failed
ActiveRecord::NotNullViolation: PG::NotNullViolation: ERROR:  null value in column "fact_name_id" violates not-null constraint
DETAIL:  Failing row contains (431, null, null, 7, 2019-04-02 12:06:14.357153, 2019-04-02 12:06:14.357153).
: INSERT INTO "fact_values" ("host_id", "updated_at", "created_at") VALUES ($1, $2, $3) RETURNING "id"

extended log output is below.

Foreman and Proxy versions:
foreman 1.21
smart_proxy_chef (0.2.0)
on the chef clients: chef_handler_foreman (0.2.0)

Other relevant data:

foreman chef proxy configuration:
:enabled: true
:chef_authenticate_nodes: true
:chef_server_url: https://chef-server.example.com
:chef_smartproxy_clientname: foreman
:chef_smartproxy_privatekey: /etc/foreman-proxy/foreman.pem
:chef_ssl_verify: false

chef-client client.rb file:
log_level :info
log_location STDOUT
chef_server_url ‘https://chef-server.example.com’
ssl_verify_mode :verify_none
validation_client_name ‘chef-validator’
validation_key ‘/etc/chef/chef-validator.pem’
node_name ‘opvitlinfor001.example.com’
require ‘chef_handler_foreman’
foreman_server_options :url => ‘https://opvitlinfor001.vitc-linux.visma.com:8443’
foreman_facts_upload true
foreman_reports_upload 'true,2 ’
foreman_enc true

2019-04-02T12:06:00 [I|app|f4655b1b] Started GET "/node/adm-acp-td936.example.com?format=yml" for 10.55.9.27 at 2019-04-02 12:06:00 +0000
2019-04-02T12:06:00 [I|app|f4655b1b] Processing by HostsController#externalNodes as YML
2019-04-02T12:06:00 [I|app|f4655b1b]   Parameters: {"name"=>"adm-acp-td936.example.com", "host"=>{}}
2019-04-02T12:06:00 [D|app|f4655b1b] Examining client certificate to extract dn and sans
2019-04-02T12:06:00 [D|app|f4655b1b] Client sent certificate with subject 'opvitlinfor001.example.com' and subject alt names '["opvitlinfor001.example.com", "puppet", "puppet.example.com"]'
2019-04-02T12:06:00 [D|app|f4655b1b] Verifying request from ["opvitlinfor001.example.com", "puppet", "puppet.example.com"] against ["opvitlinfor001.example.com"]
2019-04-02T12:06:00 [D|app|f4655b1b] Current user set to foreman_api_admin (admin)
2019-04-02T12:06:00 [I|app|f4655b1b]   Rendering text template
2019-04-02T12:06:00 [I|app|f4655b1b]   Rendered text template (0.0ms)
2019-04-02T12:06:00 [I|app|f4655b1b] Completed 200 OK in 175ms (Views: 0.4ms | ActiveRecord: 33.0ms)
2019-04-02T12:06:10 [I|app|4470d5d5] Started POST "/api/hosts/facts" for 10.55.9.27 at 2019-04-02 12:06:10 +0000
2019-04-02T12:06:10 [I|app|4470d5d5] Processing by Api::V2::HostsController#facts as JSON
2019-04-02T12:06:10 [I|app|4470d5d5]   Parameters: {"name"=>"adm-acp-td936.example.com", "facts"=>"[FILTERED]", "apiv"=>"v2", "host"=>{"name"=>"adm-acp-td936.example.com"}}
2019-04-02T12:06:10 [D|app|4470d5d5] Examining client certificate to extract dn and sans
2019-04-02T12:06:10 [D|app|4470d5d5] Client sent certificate with subject 'opvitlinfor001.example.com' and subject alt names '["opvitlinfor001.example.com", "puppet", "puppet.example.com"]'
2019-04-02T12:06:10 [D|app|4470d5d5] Verifying request from ["opvitlinfor001.example.com", "puppet", "puppet.example.com"] against ["opvitlinfor001.example.com"]
2019-04-02T12:06:10 [D|app|4470d5d5] Current user set to foreman_api_admin (admin)
2019-04-02T12:06:14 [W|app|4470d5d5] Action failed
ActiveRecord::NotNullViolation: PG::NotNullViolation: ERROR:  null value in column "fact_name_id" violates not-null constraint
DETAIL:  Failing row contains (431, null, null, 7, 2019-04-02 12:06:14.357153, 2019-04-02 12:06:14.357153).
: INSERT INTO "fact_values" ("host_id", "updated_at", "created_at") VALUES ($1, $2, $3) RETURNING "id"

/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603:in `async_exec'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603:in `block (2 levels) in exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:602:in `block in exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:579:in `block (2 levels) in log'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:578:in `block in log'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:569:in `log'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:601:in `exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:590:in `execute_and_clear'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:117:in `exec_insert'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:115:in `exec_insert'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:149:in `insert'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `insert'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/persistence.rb:187:in `_insert_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/persistence.rb:733:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/counter_cache.rb:184:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/locking/optimistic.rb:70:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/attribute_methods/dirty.rb:137:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:346:in `block in _create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:132:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_create_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:346:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/timestamp.rb:102:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/persistence.rb:704:in `create_or_update'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `block in create_or_update'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:132:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/persistence.rb:308:in `save!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/validations.rb:52:in `save!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:315:in `block in save!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:252:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:315:in `save!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:48:in `save!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:375:in `insert_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/has_many_association.rb:36:in `insert_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:361:in `block (2 levels) in _create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:458:in `replace_on_target'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:282:in `add_to_target'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:360:in `block in _create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:134:in `block in transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:252:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:133:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_association.rb:358:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/has_many_association.rb:123:in `_create_record'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/association.rb:186:in `create!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/associations/collection_proxy.rb:366:in `create!'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_chef-0.8.1/app/models/foreman_chef/fact_importer.rb:67:in `add_fact'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_chef-0.8.1/app/models/foreman_chef/fact_importer.rb:60:in `block in add_missing_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_chef-0.8.1/app/models/foreman_chef/fact_importer.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_chef-0.8.1/app/models/foreman_chef/fact_importer.rb:32:in `add_missing_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_chef-0.8.1/app/models/foreman_chef/fact_importer.rb:27:in `add_new_facts'
/usr/share/foreman/app/services/fact_importer.rb:61:in `block in import!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `block in transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/app/services/fact_importer.rb:58:in `import!'
/usr/share/foreman/app/models/host/base.rb:147:in `block in import_facts'
/usr/share/foreman/app/services/foreman/telemetry_helper.rb:27:in `telemetry_duration_histogram'
/usr/share/foreman/app/models/host/base.rb:146:in `import_facts'
/usr/share/foreman/app/models/host/managed.rb:320:in `import_facts'
/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:288:in `facts'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/static_dispatcher.rb:65:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/extractor/recorder.rb:137:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/etag.rb:25:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/conditional_get.rb:38:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/head.rb:12:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232:in `context'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:68:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `call'
/usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
/usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

2019-04-02T12:06:14 [I|app|4470d5d5]   Rendering api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout
2019-04-02T12:06:14 [I|app|4470d5d5]   Rendered api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout (0.4ms)
2019-04-02T12:06:14 [I|app|4470d5d5] Completed 500 Internal Server Error in 3622ms (Views: 1.0ms | ActiveRecord: 304.2ms)
2019-04-02T12:06:14 [I|app|7d010f2f] Started POST "/api/reports" for 10.55.9.27 at 2019-04-02 12:06:14 +0000
2019-04-02T12:06:14 [I|app|7d010f2f] Processing by Api::V2::ReportsController#create as JSON
2019-04-02T12:06:14 [I|app|7d010f2f]   Parameters: {"report"=>"[FILTERED]", "apiv"=>"v2"}
2019-04-02T12:06:14 [D|app|7d010f2f] Examining client certificate to extract dn and sans
2019-04-02T12:06:14 [D|app|7d010f2f] Client sent certificate with subject 'opvitlinfor001.example.com' and subject alt names '["opvitlinfor001.example.com", "puppet", "puppet.example.com"]'
2019-04-02T12:06:14 [D|app|7d010f2f] Verifying request from ["opvitlinfor001.example.com", "puppet", "puppet.example.com"] against ["opvitlinfor001.example.com"]
2019-04-02T12:06:14 [D|app|7d010f2f] Current user set to foreman_api_admin (admin)
2019-04-02T12:06:14 [D|app|7d010f2f] Processing report: {"host"=>"adm-acp-td936.example.com", "reported_at"=>"2019-04-02 12:06:02 +0000", "status"=>{"applied"=>1, "restarted"=>1, "failed"=>0, "failed_restarts"=>0, "skipped"=>0, "pending"=>0}, "metrics"=>{"resources"=>{"total"=>4}, "time"=>{"apt_package"=>0.058870121, "template"=>0.007326711, "service"=>1.117910203}}, "logs"=>[{"log"=>{"sources"=>{"source"=>"apt_package[ntp_package]"}, "messages"=>{"message"=>"[:install]"}, "level"=>"debug"}}, {"log"=>{"sources"=>{"source"=>"template[/etc/ntp.conf]"}, "messages"=>{"message"=>"create"}, "level"=>"debug"}}, {"log"=>{"sources"=>{"source"=>"service[ntp]"}, "messages"=>{"message"=>"[:enable, :restart]"}, "level"=>"notice"}}, {"log"=>{"sources"=>{"source"=>"service[ntp]"}, "messages"=>{"message"=>"[:enable, :restart]"}, "level"=>"notice"}}, {"log"=>{"sources"=>{"source"=>"Chef"}, "messages"=>{"message"=>"run"}, "level"=>"notice"}}]}
2019-04-02T12:06:14 [D|dyn|7d010f2f] ExecutionPlan 0b2000f0-18bb-4d97-b0fd-560f737194a0      pending >>  planning
2019-04-02T12:06:14 [D|dyn|7d010f2f]          Step 0b2000f0-18bb-4d97-b0fd-560f737194a0: 1   pending >>   running in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:14 [D|dyn|7d010f2f]          Step 0b2000f0-18bb-4d97-b0fd-560f737194a0: 1   running >>   success in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:14 [D|dyn|7d010f2f] ExecutionPlan 0b2000f0-18bb-4d97-b0fd-560f737194a0     planning >>   planned
2019-04-02T12:06:14 [I|app|7d010f2f] Scanning report with: Foreman::PuppetReportScanner
2019-04-02T12:06:14 [D|app|7d010f2f] Changes after scanning: {"host_id"=>[nil, 7], "reported_at"=>[nil, Tue, 02 Apr 2019 12:06:02 UTC +00:00], "status"=>[nil, 65], "metrics"=>[nil, "---\nresources: !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n  total: 4\ntime: !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n  apt_package: 0.058870121\n  template: 0.007326711\n  service: 1.117910203\n"]}
2019-04-02T12:06:14 [D|dyn|7d010f2f] ExecutionPlan a70cc0d8-5244-4cd9-8849-23492e9eae1c      pending >>  planning
2019-04-02T12:06:14 [D|dyn|7d010f2f]          Step a70cc0d8-5244-4cd9-8849-23492e9eae1c: 1   pending >>   running in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:14 [D|dyn|7d010f2f]          Step a70cc0d8-5244-4cd9-8849-23492e9eae1c: 1   running >>   success in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:14 [D|dyn|7d010f2f] ExecutionPlan a70cc0d8-5244-4cd9-8849-23492e9eae1c     planning >>   planned
2019-04-02T12:06:14 [D|dyn|7d010f2f] ExecutionPlan 912b9aac-389d-4200-8241-5e38316c94de      pending >>  planning
2019-04-02T12:06:14 [D|dyn|7d010f2f]          Step 912b9aac-389d-4200-8241-5e38316c94de: 1   pending >>   running in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:15 [D|dyn|7d010f2f]          Step 912b9aac-389d-4200-8241-5e38316c94de: 1   running >>   success in phase     Plan Actions::ForemanChef::Host::Update
2019-04-02T12:06:15 [D|dyn|7d010f2f] ExecutionPlan 912b9aac-389d-4200-8241-5e38316c94de     planning >>   planned
2019-04-02T12:06:15 [I|app|7d010f2f] Imported report for adm-acp-td936.example.com in 421.8 ms, status refreshed in 205.0 ms
2019-04-02T12:06:15 [I|app|7d010f2f]   Rendering api/v2/reports/create.json.rabl
2019-04-02T12:06:15 [I|app|7d010f2f]   Rendered api/v2/reports/create.json.rabl (12.4ms)
2019-04-02T12:06:15 [D|app|7d010f2f] Body: {"metrics":{"resources":{"total":4},"time":{"apt_package":0.058870121,"template":0.007326711,"service":1.117910203}},"created_at":"2019-04-02 12:06:14 UTC","updated_at":"2019-04-02 12:06:14 UTC","id":257,"host_id":7,"host_name":"adm-acp-td936.example.com","reported_at":"2019-04-02 12:06:02 UTC","status":{"applied":1,"restarted":1,"failed":0,"failed_restarts":0,"skipped":0,"pending":0},"logs":[{"level":"debug","source":{"source":"apt_package[ntp_package]"},"message":{"message":"[:install]"}},{"level":"debug","source":{"source":"template[/etc/ntp.conf]"},"message":{"message":"create"}},{"level":"notice","source":{"source":"service[ntp]"},"message":{"message":"[:enable, :restart]"}},{"level":"notice","source":{"source":"service[ntp]"},"message":{"message":"[:enable, :restart]"}},{"level":"notice","source":{"source":"Chef"},"message":{"message":"run"}}],"summary":"Modified"}
2019-04-02T12:06:15 [I|app|7d010f2f] Completed 201 Created in 653ms (Views: 11.0ms | ActiveRecord: 37.4ms)

can you please help me out with the configuration? let me know if any other information regarding my environment would help.

Marek_Hulan · April 3, 2019, 8:39am

Hello,

as suggested on IRC, most likely the problem is with race condition while creating facts. Consider configuring facts blacklist/whitelist to limit the amount of them.

andrp · April 3, 2019, 2:27pm

Hi Marek

I’ve tried limiting the facts.
foreman_facts_whitelist ['counters']
this is what is being sent from the chef node to foreman:

{
  :name=>"adm-acp-td936.example.com", 
  :facts=>{
    "counters::network::interfaces::lo::tx::queuelen"=>"1",
    "counters::network::interfaces::lo::tx::bytes"=>"21880",
    "counters::network::interfaces::lo::tx::packets"=>"180",
    "counters::network::interfaces::lo::tx::errors"=>"0",
    "counters::network::interfaces::lo::tx::drop"=>"0",
    "counters::network::interfaces::lo::tx::carrier"=>"0",
    "counters::network::interfaces::lo::tx::collisions"=>"0",
    "counters::network::interfaces::lo::rx::bytes"=>"21880",
    "counters::network::interfaces::lo::rx::packets"=>"180",
    "counters::network::interfaces::lo::rx::errors"=>"0",
    "counters::network::interfaces::lo::rx::drop"=>"0",
    "counters::network::interfaces::lo::rx::overrun"=>"0",
    "counters::network::interfaces::eth0::tx::queuelen"=>"1000",
    "counters::network::interfaces::eth0::tx::bytes"=>"131537466",
    "counters::network::interfaces::eth0::tx::packets"=>"170486",
    "counters::network::interfaces::eth0::tx::errors"=>"0",
    "counters::network::interfaces::eth0::tx::drop"=>"0",
    "counters::network::interfaces::eth0::tx::carrier"=>"0",
    "counters::network::interfaces::eth0::tx::collisions"=>"0",
    "counters::network::interfaces::eth0::rx::bytes"=>"107051478",
    "counters::network::interfaces::eth0::rx::packets"=>"132834",
    "counters::network::interfaces::eth0::rx::errors"=>"0",
    "counters::network::interfaces::eth0::rx::drop"=>"11",
    "counters::network::interfaces::eth0::rx::overrun"=>"0",
    :environment=>"_default",
    :chef_node_name=>"adm-acp-td936.example.com",
    :operatingsystem=>"Debian",
    :operatingsystemrelease=>"9.8",
    :_timestamp=>2019-04-03 11:56:58 +0000,
    :_type=>"foreman_chef"
    }
}

the same error appears - so I guess it’s not an issue that can be solved with whitelisting/blacklisting attributes.
I tried to get more debug output from the fact_importer.rb but unfortunately I wasn’t able to do that.

I’ll wait till you have more time for this.

andrp · April 12, 2019, 7:53am

Hi,

So for the last week I’ve been trying to dig deeper into this.
I’ve re-installed foreman 3 times.
my steps are described here:

install foreman using foreman-installer

installation code

foreman-installer
–foreman-initial-admin-password somepassword
–enable-foreman
–enable-foreman-cli
–enable-foreman-plugin-chef
–enable-foreman-plugin-tasks
–enable-foreman-plugin-remote-execution
–enable-foreman-proxy-plugin-remote-execution-ssh
–enable-foreman-proxy-plugin-chef
–enable-foreman-compute-vmware
–enable-foreman-compute-ec2
–foreman-proxy-plugin-chef-server-url=“https://chef-server.example.com”
–foreman-proxy-plugin-chef-client-name=“foreman”
–foreman-proxy-plugin-chef-private-key=“/etc/foreman-proxy/foreman.pem”
–foreman-proxy-plugin-chef-enabled=“true”
–foreman-proxy-plugin-chef-ssl-verify=“false”
–foreman-proxy-dns=false
–foreman-initial-location someLocation
–foreman-initial-organization someOrg
–foreman-server-ssl-crl=“”
–no-enable-puppet

create chef environment in foreman
create vmware compute-resource, create OS and update architectures, create compute-resource-image.
fix mismatch reports from Organization management
create compute profile, provisioning template, subnet, hostgroup
create one VM from foreman using VMWare - centos 7
import one existing VM from VMWare into Foreman - debian 9

Since all my vms are already bootstrapped to the chef-server, I manually configure the chef-client

client.rb configuration

/opt/chef/embedded/bin/gem install chef_handler_foreman

require ‘chef_handler_foreman’
foreman_server_options :url => ‘https://opvitlinfor003.example.com:8443’
foreman_facts_upload true
foreman_reports_upload 'true,2 ’
foreman_enc true, ‘automatic’

Whenever I run the chef-client from any of the 3 vms ( foreman server, centos vm or debian vm) I get the same error message in production.log

error message

Parameters: {"name"=>"foreman-test005.example.com", "facts"=>"[FILTERED]", "apiv"=>"v2", "host"=>{"name"=>"foreman-test005.example.com"}}
2019-04-12T07:26:01 [W|app|17114b99] Action failed
ActiveRecord::NotNullViolation: PG::NotNullViolation: ERROR:  null value in column "fact_name_id" violates not-null constraint
DETAIL:  Failing row contains (354, null, null, 2, 2019-04-12 07:26:01.08381, 2019-04-12 07:26:01.08381).
: INSERT INTO "fact_values" ("host_id", "updated_at", "created_at") VALUES ($1, $2, $3) RETURNING "id"

Reports are incoming ok, but facts fail to appear. What am I doing wrong ?

What I find strange is that it only shows 1 host in my chef environment - which is the foreman server.

Also the button: Import from … chef server doesn’t appear to be working properly in my case. If I click it, I get the error:

Please help.

andrp · April 12, 2019, 2:11pm

just a note - sending facts via api seems to work fine:

fact.json

{
“name” : “foreman-test005.example.com”,
“certname” : “optional.certname.for.this.host”,
“facts” : {
“fact1” : “value”,
“fact2” : “value”,
“fact2::nested::fact” : “value”,
“_timestamp” : “2013-10-18 07:47:45 +0000”,
“_type” : “puppet”,
“operatingsystem” : “Debian”,
“operatingsystemrelease” : “7.0”
}
}

curl -k --header "Content-Type: application/json" --request POST --data @fact.json https://admin:password@opvitlinfor003.example.com/api/hosts/facts

no errors in log

2019-04-12T14:08:04 [I|app|8885d2ec] Started POST “/api/hosts/facts” for 10.55.9.33 at 2019-04-12 14:08:04 +0000
2019-04-12T14:08:04 [I|app|8885d2ec] Processing by Api::V2::HostsController#facts as JSON
2019-04-12T14:08:04 [I|app|8885d2ec] Parameters: {“name”=>“foreman-test005.example.com”, “certname”=>“optional.certname.for.this.host”, “facts”=>"[FILTERED]", “apiv”=>“v2”, “host”=>{“certname”=>“optional.certname.for.this.host”, “name”=>“foreman-test005.example.com”}}
2019-04-12T14:08:04 [W|app|8885d2ec] No SSL cert with CN supplied - request from 10.10.10.10,
2019-04-12T14:08:04 [I|app|8885d2ec] Authorized user admin(Admin User)
2019-04-12T14:08:04 [I|app|8885d2ec] Current user set to admin (admin)
2019-04-12T14:08:04 [I|app|8885d2ec] Current user set to admin (admin)
2019-04-12T14:08:04 [I|app|8885d2ec] Import facts for ‘foreman-test005.example.com’ completed. Added: 0, Updated: 0, Deleted 0 facts
2019-04-12T14:08:04 [I|app|8885d2ec] Completed 201 Created in 501ms (Views: 2.5ms | ActiveRecord: 35.3ms)

why is the api call failing when coming from chef-client ?