Comment 5 for bug 1641136

Revision history for this message
Alexei Sheplyakov (asheplyakov) wrote : Re: nova-{api,scheduler,cert,consoleauth} service fail to start due to a wrong SQL request (or a wrong DB schema?)

Apparently nova-manage db sync fails, however puppet continues deployment instead of failing or retrying:

2016-11-11T13:55:54.881170+00:00 debug: (Exec[nova-db-sync](provider=posix)) Executing '/usr/bin/nova-manage db sync'
2016-11-11T13:55:54.881389+00:00 debug: Executing '/usr/bin/nova-manage db sync'
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) Option "verbose" from group "DEFAULT" is deprecated for removal. Its value may be silently ignored in the future.
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) Option "notification_driver" from group "DEFAULT" is deprecated. Use option "driver" from group "oslo_messaging_notifications".
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) Option "notification_topics" from group "DEFAULT" is deprecated. Use option "topics" from group "oslo_messaging_notifications".
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) /usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:450: Warning: Duplicate index 'block_device_mapping_instance_uuid_virtual_name_device_name_idx' defined on the table 'nova.block_device_mapping'. This is deprecated and will be disallowed in a future release.
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) cursor.execute(statement, parameters)
2016-11-11T13:58:45.465663+00:00 notice: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]/returns) error: (_mysql_exceptions.OperationalError) (2006, 'MySQL server has gone away')
2016-11-11T13:58:45.465663+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) Failed to call refresh: /usr/bin/nova-manage db sync returned 1 instead of one of [0]
2016-11-11T13:58:45.465663+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util/errors.rb:106:in `fail'
2016-11-11T13:58:45.465663+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/type/exec.rb:160:in `sync'
2016-11-11T13:58:45.465663+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/type/exec.rb:583:in `refresh'
2016-11-11T13:58:45.465788+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:101:in `process_callbac
k'
2016-11-11T13:58:45.465908+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:20:in `block in process
_events'
2016-11-11T13:58:45.465908+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:93:in `block in queued_
events'
2016-11-11T13:58:45.466018+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:92:in `each'
2016-11-11T13:58:45.466125+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:92:in `queued_events'
2016-11-11T13:58:45.466218+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/event_manager.rb:19:in `process_events'
2016-11-11T13:58:45.466218+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction.rb:221:in `eval_resource'
2016-11-11T13:58:45.466275+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction.rb:147:in `call'
2016-11-11T13:58:45.466340+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction.rb:147:in `block (2 levels) in evaluate'
2016-11-11T13:58:45.466406+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util.rb:335:in `block in thinmark'
2016-11-11T13:58:45.466471+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/1.9.1/benchmark.rb:295:in `realtime'
2016-11-11T13:58:45.466536+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util.rb:334:in `thinmark'
2016-11-11T13:58:45.466601+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction.rb:147:in `block in evaluate'
2016-11-11T13:58:45.466667+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:118:in `traverse'
2016-11-11T13:58:45.466732+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction.rb:138:in `evaluate'
2016-11-11T13:58:45.466796+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:169:in `block in apply'
2016-11-11T13:58:45.466861+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util/log.rb:149:in `with_destination'
2016-11-11T13:58:45.466925+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/transaction/report.rb:112:in `as_logging_destination
'
2016-11-11T13:58:45.467046+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:168:in `apply'
2016-11-11T13:58:45.467108+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/configurer.rb:120:in `block in apply_catalog'
2016-11-11T13:58:45.467338+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util.rb:161:in `block in benchmark'
2016-11-11T13:58:45.467403+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/1.9.1/benchmark.rb:295:in `realtime'
2016-11-11T13:58:45.467403+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util.rb:160:in `benchmark'
2016-11-11T13:58:45.467403+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/configurer.rb:119:in `apply_catalog'
2016-11-11T13:58:45.467403+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/configurer.rb:227:in `run_internal'
2016-11-11T13:58:45.467446+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/configurer.rb:134:in `block in run'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/context.rb:64:in `override'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet.rb:246:in `override'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/configurer.rb:133:in `run'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:302:in `apply_catalog'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:236:in `block in main'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/context.rb:64:in `override'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet.rb:246:in `override'
2016-11-11T13:58:45.467715+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:198:in `main'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:159:in `run_command'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application.rb:381:in `block (2 levels) in run'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application.rb:507:in `plugin_hook'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application.rb:381:in `block in run'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util.rb:496:in `exit_on_fail'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/application.rb:381:in `run'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util/command_line.rb:146:in `run'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/lib/ruby/vendor_ruby/puppet/util/command_line.rb:92:in `execute'
2016-11-11T13:58:45.469588+00:00 err: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) /usr/bin/puppet:8:in `<main>'
2016-11-11T13:58:45.469588+00:00 info: (/Stage[main]/Nova::Db::Sync/Exec[nova-db-sync]) Evaluated in 170.59 seconds
2016-11-11T13:58:45.469588+00:00 info: (/Stage[main]/Nova::Deps/Anchor[nova::dbsync::end]) Starting to evaluate the resource
2016-11-11T13:58:45.469824+00:00 info: (/Stage[main]/Nova::Deps/Anchor[nova::dbsync::end]) Evaluated in 0.00 seconds

[skipped]

2016-11-11T13:59:09.701859+00:00 info: (/Stage[main]/Nova::Api/Nova::Generic_service[api]/Service[nova-api]) Starting to evaluate the resource
2016-11-11T13:59:09.702940+00:00 debug: Executing '/sbin/status nova-api'
2016-11-11T13:59:09.719593+00:00 debug: Executing '/sbin/initctl --version'
2016-11-11T13:59:09.732038+00:00 debug: Executing '/sbin/start nova-api'