Error on Proxy Startup with Ansible Proxy Plugin

Support
, ,
1

Problem: When installing “ruby-smart-proxy-ansible” Plugin the Proxy is not starting up.
That happens on Foreman 1.16, 1.18 and 1.19 (now testing with 1.19)
It does not change if Proxy is installed on Foreman or standalone proxy server.
Tried out a couple of ansible version. (2.2.0, 2.3.1, 2.6, 2.7)
No matter if I install proxy and with “foreman-installer” or with “apt-get install”.
Always the same outcome.

I am testing on Ubuntu 16.04.5 LTS

Expected outcome: proxy server starting

Foreman and Proxy versions: foreman-proxy 1.19.0-1

Foreman and Proxy plugin versions: ruby-smart-proxy-ansible 2.0.3-2
ruby-smart-proxy-dynflow-core 0.2.1-1
ruby-smart-proxy-dynflow 0.2.1-1

Other relevant data:

root@ubuntu-xenial:/home/vagrant# foreman-installer --no-enable-foreman --no-enable-foreman-cli --enable-foreman-proxy-plugin-ansible
 /Stage[main]/Foreman_proxy::Service/Service[foreman-proxy]: Failed to call refresh: Systemd restart for foreman-proxy failed!
journalctl log for foreman-proxy:
-- Logs begin at Wed 2018-10-17 05:34:32 UTC, end at Wed 2018-10-17 05:37:23 UTC. --
Oct 17 05:34:38 ubuntu-xenial systemd[1]: Starting Foreman Proxy...
Oct 17 05:34:46 ubuntu-xenial smart-proxy[1156]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Oct 17 05:34:46 ubuntu-xenial smart-proxy[1156]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Oct 17 05:34:46 ubuntu-xenial systemd[1]: Started Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: Stopping Foreman Proxy...
Oct 17 05:37:22 proxy1 systemd[1]: Stopped Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: Starting Foreman Proxy...
Oct 17 05:37:22 proxy1 smart-proxy[3302]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Oct 17 05:37:22 proxy1 smart-proxy[3302]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Running Foreman Ansible Core in non-SCL context
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Running Foreman Ansible Core in non-SCL context
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Errors detected on startup, see log for details. Exiting: settings ansible already registered
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Main process exited, code=exited, status=1/FAILURE
Oct 17 05:37:22 proxy1 systemd[1]: Failed to start Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Unit entered failed state.
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Failed with result 'exit-code'.
 /Stage[main]/Foreman_proxy::Service/Service[foreman-proxy]: Systemd restart for foreman-proxy failed!
journalctl log for foreman-proxy:
-- Logs begin at Wed 2018-10-17 05:34:32 UTC, end at Wed 2018-10-17 05:37:23 UTC. --
Oct 17 05:34:38 ubuntu-xenial systemd[1]: Starting Foreman Proxy...
Oct 17 05:34:46 ubuntu-xenial smart-proxy[1156]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Oct 17 05:34:46 ubuntu-xenial smart-proxy[1156]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Oct 17 05:34:46 ubuntu-xenial systemd[1]: Started Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: Stopping Foreman Proxy...
Oct 17 05:37:22 proxy1 systemd[1]: Stopped Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: Starting Foreman Proxy...
Oct 17 05:37:22 proxy1 smart-proxy[3302]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Oct 17 05:37:22 proxy1 smart-proxy[3302]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Running Foreman Ansible Core in non-SCL context
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Running Foreman Ansible Core in non-SCL context
Oct 17 05:37:22 proxy1 smart-proxy[3302]: Errors detected on startup, see log for details. Exiting: settings ansible already registered
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Main process exited, code=exited, status=1/FAILURE
Oct 17 05:37:22 proxy1 systemd[1]: Failed to start Foreman Proxy.
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Unit entered failed state.
Oct 17 05:37:22 proxy1 systemd[1]: foreman-proxy.service: Failed with result 'exit-code'.

/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/provider/service/systemd.rb:159:in `rescue in restart'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/provider/service/systemd.rb:155:in `restart'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/service.rb:248:in `refresh'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:147:in `process_callback'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:34:in `block in process_events'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:119:in `block in queued_events'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:118:in `each'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:118:in `queued_events'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:33:in `process_events'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:278:in `eval_resource'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `call'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `block (2 levels) in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:515:in `block in thinmark'
/opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:514:in `thinmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:121:in `traverse'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:171:in `evaluate'
/usr/lib/ruby/vendor_ruby/kafo/modules/kafo_configure/lib/puppet/parser/functions/add_progress.rb:30:in `evaluate_with_trigger'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:239:in `block (2 levels) in apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:515:in `block in thinmark'
/opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:514:in `thinmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:238:in `block in apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/log.rb:156:in `with_destination'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/report.rb:146:in `as_logging_destination'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:237:in `apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:186:in `block (2 levels) in apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:515:in `block in thinmark'
/opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:514:in `thinmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:185:in `block in apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:232:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:231:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:184:in `apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:369:in `run_internal'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:237:in `block in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:211:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:354:in `apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:280:in `block (2 levels) in main'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:280:in `block in main'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:233:in `main'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:174:in `run_command'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:375:in `block in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:663:in `exit_on_fail'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:375:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:136:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:73:in `execute'
/opt/puppetlabs/puppet/bin/puppet:5:in `<main>'
2

What do the logs say? Also it might be useful to bump the log level to debug in /etc/foreman-proxy/settings.yml, restart the service and look into the logs after that.

3

here is the requested log output, level debug

D, [2018-10-17T09:33:52.355275 ] DEBUG -- : 'dynflow' settings: 'core_url': https://proxy1.nts.at:8008, 'database': , 'enabled': https

D, [2018-10-17T09:33:52.356103 ] DEBUG -- : 'dynflow' ports: 'http': false, 'https': true

D, [2018-10-17T09:33:52.362192 ] DEBUG -- : 'ansible' settings: 'ansible_working_dir': ~/.foreman-ansible, 'enabled': true

D, [2018-10-17T09:33:52.363585 ] DEBUG -- : 'ansible' ports: 'http': true, 'https': true

D, [2018-10-17T09:33:52.375765 ] DEBUG -- : 'tftp' settings: 'enabled': https, 'tftp_connect_timeout': 10 (default), 'tftp_dns_timeout': 10 (default), 'tftp_read_timeout': 60 (default), 'tftproot': /var/lib/tftpboot (default)

D, [2018-10-17T09:33:52.376940 ] DEBUG -- : 'tftp' ports: 'http': false, 'https': true

D, [2018-10-17T09:33:52.387228 ] DEBUG -- : 'puppetca' settings: 'enabled': https, 'ssldir': /etc/puppetlabs/puppet/ssl, 'use_provider': puppetca_hostname_whitelisting (default)

D, [2018-10-17T09:33:52.388583 ] DEBUG -- : 'puppetca' ports: 'http': false, 'https': true

D, [2018-10-17T09:33:52.426086 ] DEBUG -- : 'puppet' settings: 'enabled': https, 'puppet_version': 5.5.6, 'use_provider': [:puppet_proxy_puppet_api]

D, [2018-10-17T09:33:52.427505 ] DEBUG -- : 'puppet' ports: 'http': false, 'https': true

D, [2018-10-17T09:33:52.435311 ] DEBUG -- : 'logs' settings: 'enabled': https

D, [2018-10-17T09:33:52.435920 ] DEBUG -- : 'logs' ports: 'http': false, 'https': true

D, [2018-10-17T09:33:52.437311 ] DEBUG -- : Providers ['puppetca_hostname_whitelisting'] are going to be configured for 'puppetca'

D, [2018-10-17T09:33:52.438685 ] DEBUG -- : Providers ['puppet_proxy_puppet_api'] are going to be configured for 'puppet'

D, [2018-10-17T09:33:52.447841 ] DEBUG -- : 'puppetca_hostname_whitelisting' settings: 'autosignfile': /etc/puppetlabs/puppet/autosign.conf, 'ssldir': /etc/puppetlabs/puppet/ssl, 'use_provider': puppetca_hostname_whitelisting

D, [2018-10-17T09:33:52.459720 ] DEBUG -- : 'puppet_proxy_puppet_api' settings: 'api_timeout': 30 (default), 'classes_retriever': apiv3, 'environments_retriever': apiv3, 'puppet_ssl_ca': /etc/puppetlabs/puppet/ssl/certs/ca.pem, 'puppet_ssl_cert': /etc/puppetlabs/puppet/ssl/certs/proxy1.nts.at.pem, 'puppet_ssl_key': /etc/puppetlabs/puppet/ssl/private_keys/proxy1.nts.at.pem, 'puppet_url': https://proxy1.nts.at:8140, 'puppet_version': 5.5.6, 'use_provider': [:puppet_proxy_puppet_api]

I, [2018-10-17T09:33:52.463464 ] INFO -- : Successfully initialized 'dynflow'

I, [2018-10-17T09:33:52.490189 ] INFO -- : Successfully initialized 'ansible'

I, [2018-10-17T09:33:52.490694 ] INFO -- : Successfully initialized 'foreman_proxy'

I, [2018-10-17T09:33:52.491191 ] INFO -- : Successfully initialized 'tftp'

I, [2018-10-17T09:33:52.491680 ] INFO -- : Successfully initialized 'puppetca_hostname_whitelisting'

I, [2018-10-17T09:33:52.492204 ] INFO -- : Successfully initialized 'puppetca'

I, [2018-10-17T09:33:52.492756 ] INFO -- : Started puppet class cache initialization

I, [2018-10-17T09:33:52.493665 ] INFO -- : Successfully initialized 'puppet_proxy_puppet_api'

I, [2018-10-17T09:33:52.494141 ] INFO -- : Successfully initialized 'puppet'

D, [2018-10-17T09:33:52.494477 ] DEBUG -- : Log buffer API initialized, available capacity: 2000/1000

I, [2018-10-17T09:33:52.494884 ] INFO -- : Successfully initialized 'logs'

I, [2018-10-17T09:33:52.497957 #2747] INFO -- : Settings loaded, reloading logger

E, [2018-10-17T09:33:52.501333 ] ERROR -- : Error during startup, terminating. settings ansible already registered

D, [2018-10-17T09:33:52.501766 ] DEBUG -- : ["/usr/share/foreman-proxy/lib/launcher.rb:65:in `instance_eval'", "/usr/lib/ruby/vendor_ruby/foreman_tasks_core/settings_loader.rb:21:in `each'", "/usr/lib/ruby/vendor_ruby/foreman_tasks_core/settings_loader.rb:21:in `register_settings'", "/usr/lib/ruby/vendor_ruby/foreman_tasks_core/settings_loader.rb:35:in `register_settings'", "/usr/lib/ruby/vendor_ruby/foreman_ansible_core.rb:18:in `&lt;module:ForemanAnsibleCore&gt;'", "/usr/lib/ruby/vendor_ruby/foreman_ansible_core.rb:11:in `&lt;top (required)&gt;'", "/usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'", "/usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'", "/usr/lib/ruby/vendor_ruby/smart_proxy_ansible/api.rb:1:in `&lt;top (required)&gt;'", "/usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'", "/usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'", "(eval):1:in `block (2 levels) in https_app'", "/usr/share/foreman-proxy/lib/launcher.rb:65:in `instance_eval'", "/usr/share/foreman-proxy/lib/launcher.rb:65:in `block (2 levels) in https_app'", "/usr/share/foreman-proxy/lib/launcher.rb:65:in `each'", "/usr/share/foreman-proxy/lib/launcher.rb:65:in `block in https_app'", "/usr/lib/ruby/vendor_ruby/rack/builder.rb:55:in `instance_eval'", "/usr/lib/ruby/vendor_ruby/rack/builder.rb:55:in `initialize'", "/usr/share/foreman-proxy/lib/launcher.rb:64:in `new'", "/usr/share/foreman-proxy/lib/launcher.rb:64:in `https_app'", "/usr/share/foreman-proxy/lib/launcher.rb:169:in `launch'", "/usr/share/foreman-proxy/bin/smart-proxy:6:in `&lt;main&gt;'"]
4

We’re now aware of this issue. Until it gets fixed properly, running the following should unblock you.

sed --in-place=.bak "s/^\(require 'foreman_ansible_core'\)/# \1/" \
    /usr/lib/ruby/vendor_ruby/smart_proxy_ansible/api.rb
5

Perfekt! Works!
thx a lot