Foreman 17.0 RC1 problem

Tobias_Koeck · February 27, 2018, 7:27pm

Debian 9 AMD 64
Foreman 17.0 RC1

** Log Output **

[ WARN 2018-02-27T20:23:07 main]  /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:       from /usr/lib/ruby/2.3.0/rubygems/core_ext/k
ernel_require.rb:55:in `require'
[ERROR 2018-02-27T20:23:07 main]  /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]: Failed to call refresh: '/usr/sbin/foreman-rake db:migrate' returned 1 instead of one of [0]
[ERROR 2018-02-27T20:23:07 main]  /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]: '/usr/sbin/foreman-rake db:migrate' returned 1 instead of one of [0]
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/errors.rb:157:in `fail'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/exec.rb:164:in `sync'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/exec.rb:604:in `refresh'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:147:in `process_callback'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:34:in `block in process_events'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:119:in `block in queued_events'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:118:in `each'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:118:in `queued_events'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:33:in `process_events'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:278:in `eval_resource'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `call'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `block (2 levels) in evaluate'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:517:in `block in thinmark'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:516:in `thinmark'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:181:in `block in evaluate'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:121:in `traverse'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:171:in `evaluate'
[ERROR 2018-02-27T20:23:07 main] /usr/lib/ruby/vendor_ruby/kafo/modules/kafo_configure/lib/puppet/parser/functions/add_progress.rb:30:in `evaluate_with_trigger'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:238:in `block in apply'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/log.rb:156:in `with_destination'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/report.rb:144:in `as_logging_destination'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:237:in `apply'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:174:in `block in apply_catalog'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:232:in `block in benchmark'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:231:in `benchmark'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:173:in `apply_catalog'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:348:in `run_internal'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:224:in `block in run'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:198:in `run'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:354:in `apply_catalog'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:280:in `block (2 levels) in main'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:280:in `block in main'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:260:in `override'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:233:in `main'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:174:in `run_command'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:375:in `block in run'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:665:in `exit_on_fail'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:375:in `run'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:137:in `run'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:73:in `execute'
[ERROR 2018-02-27T20:23:07 main] /opt/puppetlabs/puppet/bin/puppet:5:in `<main>'

Problem occured after adding

[✓] Configure foreman_plugin_tasks

and

[✓] Configure foreman_plugin_ansible

root@foreman:/home/tkoeck# apt-get install
Reading package lists... Done
Building dependency tree
Reading state information... Done
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
3 not fully installed or removed.
After this operation, 0 B of additional disk space will be used.
Setting up ruby-foreman-deface (1.2.0-1) ...
dpkg: error processing package ruby-foreman-deface (--configure):
 subprocess installed post-installation script returned error exit status 6
dpkg: dependency problems prevent configuration of ruby-foreman-azure:
 ruby-foreman-azure depends on ruby-foreman-deface (<< 2.0.0); however:
  Package ruby-foreman-deface is not configured yet.

dpkg: error processing package ruby-foreman-azure (--configure):
 dependency problems - leaving unconfigured
dpkg: dependency problems prevent configuration of ruby-foreman-ansible:
 ruby-foreman-ansible depends on ruby-foreman-deface (<< 2.0.0); however:
  Package ruby-foreman-deface is not configured yet.

dpkg: error processing package ruby-foreman-ansible (--configure):
 dependency problems - leaving unconfigured
Errors were encountered while processing:
 ruby-foreman-deface
 ruby-foreman-azure
 ruby-foreman-ansible

iNecas · February 28, 2018, 4:37pm

This backtrace is not very helpful, as it’s just from the puppet code. In /var/log/foreman/production.log there should be more relevant backtrace from the action migration.

dLobatog · March 1, 2018, 10:45am

Are you able to just apt-get install ruby-foreman-deface?

Tobias_Koeck · March 1, 2018, 11:30am

Hi, no that doesn’t work either

root@foreman:/home/tkoeck# apt-get install ruby-foreman-deface
Reading package lists… Done
Building dependency tree
Reading state information… Done
ruby-foreman-deface is already the newest version (1.2.0-1).
ruby-foreman-deface set to manually installed.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
3 not fully installed or removed.
After this operation, 0 B of additional disk space will be used.
Do you want to continue? [Y/n]
Setting up ruby-foreman-deface (1.2.0-1) …
dpkg: error processing package ruby-foreman-deface (–configure):
subprocess installed post-installation script returned error exit status 6
dpkg: dependency problems prevent configuration of ruby-foreman-azure:
ruby-foreman-azure depends on ruby-foreman-deface (<< 2.0.0); however:
Package ruby-foreman-deface is not configured yet.

dpkg: error processing package ruby-foreman-azure (–configure):
dependency problems - leaving unconfigured
dpkg: dependency problems prevent configuration of ruby-foreman-ansible:
ruby-foreman-ansible depends on ruby-foreman-deface (<< 2.0.0); however:
Package ruby-foreman-deface is not configured yet.

dpkg: error processing package ruby-foreman-ansible (–configure):
dependency problems - leaving unconfigured
Errors were encountered while processing:
ruby-foreman-deface
ruby-foreman-azure
ruby-foreman-ansible
E: Sub-process /usr/bin/dpkg returned an error code (1)

I could attach the foreman logs as well if it is needed. I have installed The Foreman 17.0 RC1 right after installing a vanilla Debian 9 system.

ekohl · March 1, 2018, 11:33am

The logs are indeed needed. There’s a database migration that’s gone wrong and we need some details why that happened.

Tobias_Koeck · March 1, 2018, 11:40am

I have attached the log and changed some passwords in the log file.

foreman.log.gz (86.9 KB)

These are one-time generic password which will change in the future but is there a way to dump log files without potential problematic credentials/passwrds?

ekohl · March 1, 2018, 12:01pm

Could you upload the one @iNecas mentioned? /var/log/foreman/production.log probably contains the actual logs we’re interested in.

There isn’t.

Tobias_Koeck · March 1, 2018, 12:12pm

Here we go.
production.log.gz (47.5 KB)

ekohl · March 1, 2018, 1:31pm

Relevant part of the log:

2018-02-27T18:23:12  [app] [E] Error performing CreateRssNotifications (Job ID: a74bf7ca-8ef5-4d75-84f2-4772bcbb6305) from Dynflow(default) in 29.33ms: ActiveRecord::StatementInvalid (PG::UndefinedTable: ERROR:  relation "settings" does not exist
 | LINE 8:                WHERE a.attrelid = '"settings"'::regclass
 |                                           ^
 | :               SELECT a.attname, format_type(a.atttypid, a.atttypmod),
 |                      pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod,
 |                      c.collname, col_description(a.attrelid, a.attnum) AS comment
 |                 FROM pg_attribute a
 |                 LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 |                 LEFT JOIN pg_type t ON a.atttypid = t.oid
 |                 LEFT JOIN pg_collation c ON a.attcollation = c.oid AND a.attcollation <> t.typcollation
 |                WHERE a.attrelid = '"settings"'::regclass
 |                  AND a.attnum > 0 AND NOT a.attisdropped
 |                ORDER BY a.attnum
 | ):

Ondrej_Prazak · March 2, 2018, 9:02am

This might be related to the rex notifications bug