Foreman 1.19 + Ansible already registered

Problem:
Cannot install foreman proxy with ansible support.
I’ve made a new VM with a brand new installation of Foreman (via foreman-installer), ansible as well as ruby-foreman-ansible, ruby-smart-proxy-dynflow and ruby-smart-proxy-ansible.

After restarting the foreman proxy service i get the error message shown below.

Expected outcome:

Foreman and Proxy versions:
ii foreman 1.19.0-1
ii foreman-proxy 1.19.0-1

Foreman and Proxy plugin versions:
ii ruby-foreman-ansible 2.2.7-1
ii ruby-foreman-deface 1.2.0-1
ii ruby-foreman-remote-execution 1.5.6-1
ii ruby-foreman-tasks 0.13.2-1
ii ruby-foreman-tasks-core 0.2.5-1
ii ruby-hammer-cli-foreman 0.14.0-1

Other relevant data:

/var/log/foreman-proxy/proxy.log
# Logfile created on 2018-09-17 17:10:35 +0200 by logger.rb/v1.2.7
I, [2018-09-17T17:10:35.636453 ] INFO – : Successfully initialized ‘dynflow’
I, [2018-09-17T17:10:35.646509 ] INFO – : Successfully initialized ‘ansible’
I, [2018-09-17T17:10:35.646599 ] INFO – : Successfully initialized ‘foreman_proxy’
I, [2018-09-17T17:10:35.646667 ] INFO – : Successfully initialized ‘tftp’
I, [2018-09-17T17:10:35.646747 ] INFO – : Successfully initialized ‘puppetca_hostname_whitelisting’
I, [2018-09-17T17:10:35.646818 ] INFO – : Successfully initialized ‘puppetca’
I, [2018-09-17T17:10:35.646964 ] INFO – : Started puppet class cache initialization
I, [2018-09-17T17:10:35.647606 ] INFO – : Successfully initialized ‘puppet_proxy_puppet_api’
I, [2018-09-17T17:10:35.647746 ] INFO – : Successfully initialized ‘puppet’
I, [2018-09-17T17:10:35.647964 ] INFO – : Successfully initialized ‘logs’
I, [2018-09-17T17:10:35.650978 #2944] INFO – : Settings loaded, reloading logger
E, [2018-09-17T17:10:35.652761 ] ERROR – : Error during startup, terminating. settings ansible already registered

I haven’t seen this error before and can’t find the string in proxy where it’s raised. Mind to try setting debug log level in /etc/foreman-proxy/settings.yml and reupload the proxy.log from proxy start?

Hi @Marek_Hulan,

thanks for the response. here’s the log you are waiting for:

Logfile

Logfile created on 2018-09-18 11:35:07 +0200 by logger.rb/v1.2.7

D, [2018-09-18T11:35:07.598125 ] DEBUG – : ‘dynflow’ settings: ‘core_url’: http://127.0.0.1:8008, ‘database’: /var/lib/foreman-proxy/dynflow/dynflow.sqlite, ‘enabled’: true

D, [2018-09-18T11:35:07.598244 ] DEBUG – : ‘dynflow’ ports: ‘http’: true, ‘https’: true

D, [2018-09-18T11:35:07.600544 ] DEBUG – : ‘ansible’ settings: ‘ansible_working_dir’: ~/.foreman-ansible, ‘enabled’: true

D, [2018-09-18T11:35:07.600611 ] DEBUG – : ‘ansible’ ports: ‘http’: true, ‘https’: true

D, [2018-09-18T11:35:07.605523 ] DEBUG – : ‘tftp’ settings: ‘enabled’: https, ‘tftp_connect_timeout’: 10 (default), ‘tftp_dns_timeout’: 10 (default), ‘tftp_read_timeout’: 60 (default), ‘tftproot’: /srv/tftp

D, [2018-09-18T11:35:07.605594 ] DEBUG – : ‘tftp’ ports: ‘http’: false, ‘https’: true

D, [2018-09-18T11:35:07.619176 ] DEBUG – : ‘puppetca’ settings: ‘enabled’: https, ‘ssldir’: /etc/puppetlabs/puppet/ssl, ‘use_provider’: puppetca_hostname_whitelisting (default)

D, [2018-09-18T11:35:07.619289 ] DEBUG – : ‘puppetca’ ports: ‘http’: false, ‘https’: true

D, [2018-09-18T11:35:07.623711 ] DEBUG – : ‘puppet’ settings: ‘enabled’: https, ‘puppet_version’: 5.5.6, ‘use_provider’: [:puppet_proxy_puppet_api]

D, [2018-09-18T11:35:07.623788 ] DEBUG – : ‘puppet’ ports: ‘http’: false, ‘https’: true

D, [2018-09-18T11:35:07.626493 ] DEBUG – : ‘logs’ settings: ‘enabled’: https

D, [2018-09-18T11:35:07.626561 ] DEBUG – : ‘logs’ ports: ‘http’: false, ‘https’: true

D, [2018-09-18T11:35:07.626872 ] DEBUG – : Providers [‘puppetca_hostname_whitelisting’] are going to be configured for ‘puppetca’

D, [2018-09-18T11:35:07.626961 ] DEBUG – : Providers [‘puppet_proxy_puppet_api’] are going to be configured for ‘puppet’

D, [2018-09-18T11:35:07.629962 ] DEBUG – : ‘puppetca_hostname_whitelisting’ settings: ‘autosignfile’: /etc/puppetlabs/puppet/autosign.conf, ‘ssldir’: /etc/puppetlabs/puppet/ssl, ‘use_provider’: puppetca_hostname_whitelisting

D, [2018-09-18T11:35:07.635319 ] 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/cm.emoto2.local.pem, ‘puppet_ssl_key’: /etc/puppetlabs/puppet/ssl/private_keys/cm.emoto2.local.pem, ‘puppet_url’: https://cm.emoto2.local:8140, ‘puppet_version’: 5.5.6, ‘use_provider’: [:puppet_proxy_puppet_api]

I, [2018-09-18T11:35:07.635973 ] INFO – : Successfully initialized ‘dynflow’

I, [2018-09-18T11:35:07.645750 ] INFO – : Successfully initialized ‘ansible’

I, [2018-09-18T11:35:07.645850 ] INFO – : Successfully initialized ‘foreman_proxy’

I, [2018-09-18T11:35:07.645917 ] INFO – : Successfully initialized ‘tftp’

I, [2018-09-18T11:35:07.645997 ] INFO – : Successfully initialized ‘puppetca_hostname_whitelisting’

I, [2018-09-18T11:35:07.646064 ] INFO – : Successfully initialized ‘puppetca’

I, [2018-09-18T11:35:07.646200 ] INFO – : Started puppet class cache initialization

I, [2018-09-18T11:35:07.646800 ] INFO – : Successfully initialized ‘puppet_proxy_puppet_api’

I, [2018-09-18T11:35:07.646871 ] INFO – : Successfully initialized ‘puppet’

D, [2018-09-18T11:35:07.647124 ] DEBUG – : Log buffer API initialized, available capacity: 2000/1000

I, [2018-09-18T11:35:07.647380 ] INFO – : Successfully initialized ‘logs’

I, [2018-09-18T11:35:07.651675 #7608] INFO – : Settings loaded, reloading logger

E, [2018-09-18T11:35:07.652696 ] ERROR – : Error during startup, terminating. settings ansible already registered

D, [2018-09-18T11:35:07.668561 ] DEBUG – : ["/usr/share/foreman-proxy/lib/launcher.rb:65:in instance_eval'", "/usr/lib/ruby/vendor_ruby/foreman_tasks_core/settings_loader.rb:21:ineach’", “/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:inregister_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<top (required)>’”, “/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:inrequire’”, “/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:inrequire’”, “/usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in require'", "(eval):1:inblock (2 levels) in https_app’”, “/usr/share/foreman-proxy/lib/launcher.rb:65:in instance_eval'", "/usr/share/foreman-proxy/lib/launcher.rb:65:inblock (2 levels) in https_app’”, “/usr/share/foreman-proxy/lib/launcher.rb:65:in each'", "/usr/share/foreman-proxy/lib/launcher.rb:65:inblock in https_app’”, “/usr/lib/ruby/vendor_ruby/rack/builder.rb:55:in instance_eval'", "/usr/lib/ruby/vendor_ruby/rack/builder.rb:55:ininitialize’”, “/usr/share/foreman-proxy/lib/launcher.rb:64:in new'", "/usr/share/foreman-proxy/lib/launcher.rb:64:inhttps_app’”, “/usr/share/foreman-proxy/lib/launcher.rb:169:in launch'", "/usr/share/foreman-proxy/bin/smart-proxy:6:in<main>’”]

Hi @Marek_Hulan

any idea on how to solve this problem?

I’ve made a small step by step installation guide on how to reproduce this error (Debian Stretch Latest basic installation)

https://pastebin.com/vMZa6CXJ

Thanks, the trace might help. I see you don’t seem to use installer for configuring ansible plugin, why is that? See foreman-installer --help | grep ansible. I don’t see anything obvious, but worth trying installing with --enable-foreman-ansible and the other option for smart proxy ansible plugin. Sorry, typing from phone so can’t check real names.

Hi @Marek_Hulan

unfortunately we’ve got the same problem with this installation method.

Logfile

sudo foreman-installer --enable-foreman-plugin-ansible --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 Thu 2018-09-27 08:03:40 CEST, end at Thu 2018-09-27 08:17:08 CEST. –
Sep 27 08:17:07 cm systemd[1]: Stopping Foreman Proxy…
Sep 27 08:17:07 cm systemd[1]: Stopped Foreman Proxy.
Sep 27 08:17:07 cm systemd[1]: Starting Foreman Proxy…
Sep 27 08:17:08 cm smart-proxy[31279]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Sep 27 08:17:08 cm smart-proxy[31279]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Sep 27 08:17:08 cm smart-proxy[31279]: Running Foreman Ansible Core in non-SCL context
Sep 27 08:17:08 cm smart-proxy[31279]: Errors detected on startup, see log for details. Exiting: settings ansible already registered
Sep 27 08:17:08 cm systemd[1]: foreman-proxy.service: Main process exited, code=exited, status=1/FAILURE
Sep 27 08:17:08 cm systemd[1]: Failed to start Foreman Proxy.
Sep 27 08:17:08 cm systemd[1]: foreman-proxy.service: Unit entered failed state.
Sep 27 08:17:08 cm 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 Thu 2018-09-27 08:03:40 CEST, end at Thu 2018-09-27 08:17:08 CEST. –
Sep 27 08:17:07 cm systemd[1]: Stopping Foreman Proxy…
Sep 27 08:17:07 cm systemd[1]: Stopped Foreman Proxy.
Sep 27 08:17:07 cm systemd[1]: Starting Foreman Proxy…
Sep 27 08:17:08 cm smart-proxy[31279]: /usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/webrick-patch.rb:3: warning: already initialized constant CIPHERS
Sep 27 08:17:08 cm smart-proxy[31279]: /usr/share/foreman-proxy/lib/webrick-patch.rb:3: warning: previous definition of CIPHERS was here
Sep 27 08:17:08 cm smart-proxy[31279]: Running Foreman Ansible Core in non-SCL context
Sep 27 08:17:08 cm smart-proxy[31279]: Errors detected on startup, see log for details. Exiting: settings ansible already registered
Sep 27 08:17:08 cm systemd[1]: foreman-proxy.service: Main process exited, code=exited, status=1/FAILURE
Sep 27 08:17:08 cm systemd[1]: Failed to start Foreman Proxy.
Sep 27 08:17:08 cm systemd[1]: foreman-proxy.service: Unit entered failed state.
Sep 27 08:17:08 cm 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:inrestart’
/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:inprocess_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:inblock 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:inqueued_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:ineval_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:inblock (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:inrealtime’
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:514:in thinmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:inblock 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:inevaluate’
/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:inblock (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:inrealtime’
/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:inblock 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:inas_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:inblock (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:inrealtime’
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:514:in thinmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:185:inblock 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:inrealtime’
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:231:in benchmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:184:inapply_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:inblock 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:inoverride’
/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:inapply_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:inoverride’
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:280:inblock 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:inoverride’
/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:inrun_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:inexit_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:inrun’
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:73:in execute' /opt/puppetlabs/puppet/bin/puppet:5:in

Please take a look at comment #4 in Error on Proxy Startup with Ansible Proxy Plugin

Hi @aruzicka,
thanks for the response! It’s working with the fix you mentioned.

Cheers!