Juju Charms Collection
nova-cloud-controller package

"nova-manage db sync" fails with IntegrityError, duplicate entry

Bug #1347245 reported by Andreas Hasenack
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
nova-cloud-controller (Juju Charms Collection)
Fix Released
Medium
Liam Young
Juju Charms Collection 15.01

Bug Description

I have been tracking https://launchpad.net/bugs/1335139, because the error was in the same command, but this might actually be a different bug.

Below if the backtrace, with long lines wrapped around making it hard to read. I'm attaching the full log too.
(...)
2014-07-22 22:26:59 INFO juju-log shared-db:15: Rendering from template: haproxy.cfg
2014-07-22 22:26:59 INFO juju-log shared-db:15: Wrote template /etc/haproxy/haproxy.cfg.
2014-07-22 22:26:59 INFO juju-log shared-db:15: Migrating the nova database.
2014-07-22 22:27:00 INFO shared-db-relation-changed 2014-07-22 22:27:00.417 7740 INFO migrate.versioning.api [-] 215 -> 216...
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 CRITICAL nova [-] IntegrityError: (IntegrityError) (1062, "Duplicate entry 'juju-machine-0-lxc-1-conductor-0' for key 'uniq_services0host0topic0deleted'") 'ALTER TABLE services ADD CONSTRAINT uniq_services0host0topic0deleted UNIQUE (host, topic, deleted)' ()
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova Traceback (most recent call last):
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/bin/nova-manage", line 10, in <module>
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova sys.exit(main())
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/cmd/manage.py", line 1374, in main
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova ret = fn(*fn_args, **fn_kwargs)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/cmd/manage.py", line 883, in sync
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return migration.db_sync(version)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/db/migration.py", line 29, in db_sync
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return IMPL.db_sync(version=version)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/migration.py", line 44, in db_sync
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return versioning_api.upgrade(get_engine(), repository, version)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/versioning/api.py", line 186, in upgrade
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return _migrate(url, repository, version, upgrade=True, err=err, **opts)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "<string>", line 2, in _migrate
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/versioning/util/__init__.py", line 159, in with_engine
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return f(*a, **kw)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/versioning/api.py", line 366, in _migrate
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova schema.runchange(ver, change, changeset.step)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/versioning/schema.py", line 91, in runchange
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova change.run(self.engine, step)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/versioning/script/py.py", line 145, in run
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova script_func(engine)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/migrate_repo/versions/216_havana.py", line 1173, in upgrade
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova name='uniq_services0host0topic0deleted').create()
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/constraint.py", line 44, in create
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova self.__do_imports('constraintgenerator', *a, **kw)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/constraint.py", line 32, in __do_imports
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova run_single_visitor(engine, visitorcallable, self, *a, **kw)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/databases/visitor.py", line 75, in run_single_visitor
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova fn(element, **kwargs)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/ansisql.py", line 290, in visit_migrate_unique_constraint
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova self._visit_constraint(*p, **k)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/ansisql.py", line 296, in _visit_constraint
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova self.execute()
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/migrate/changeset/ansisql.py", line 43, in execute
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova return self.connection.execute(self.buffer.getvalue())
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova params)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 805, in _execute_text
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova statement, parameters
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova context)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova exc_info
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 196, in raise_from_cause
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova reraise(type(exception), exception, tb=exc_tb)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova context)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova cursor.execute(statement, parameters)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova self.errorhandler(self, exc, value)
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova raise errorclass, errorvalue
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova IntegrityError: (IntegrityError) (1062, "Duplicate entry 'juju-machine-0-lxc-1-conductor-0' for key 'uniq_services0host0topic0deleted'") 'ALTER TABLE services ADD CONSTRAINT uniq_services0host0topic0deleted UNIQUE (host, topic, deleted)' ()
2014-07-22 22:27:02 INFO shared-db-relation-changed 2014-07-22 22:27:02.145 7740 TRACE nova
2014-07-22 22:27:02 INFO shared-db-relation-changed Traceback (most recent call last):
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/shared-db-relation-changed", line 511, in <module>
2014-07-22 22:27:02 INFO shared-db-relation-changed main()
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/shared-db-relation-changed", line 505, in main
2014-07-22 22:27:02 INFO shared-db-relation-changed hooks.execute(sys.argv)
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/charmhelpers/core/hookenv.py", line 478, in execute
2014-07-22 22:27:02 INFO shared-db-relation-changed self._hooks[hook_name]()
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/charmhelpers/core/host.py", line 218, in wrapped_f
2014-07-22 22:27:02 INFO shared-db-relation-changed f(*args)
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/shared-db-relation-changed", line 182, in db_changed
2014-07-22 22:27:02 INFO shared-db-relation-changed migrate_database()
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/nova_cc_utils.py", line 485, in migrate_database
2014-07-22 22:27:02 INFO shared-db-relation-changed subprocess.check_output(cmd)
2014-07-22 22:27:02 INFO shared-db-relation-changed File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
2014-07-22 22:27:02 INFO shared-db-relation-changed raise CalledProcessError(retcode, cmd, output=output)
2014-07-22 22:27:02 INFO shared-db-relation-changed subprocess.CalledProcessError: Command '['nova-manage', 'db', 'sync']' returned non-zero exit status 1
2014-07-22 22:27:02 ERROR juju.worker.uniter uniter.go:486 hook failed: exit status 1

Related branches

lp://staging/~gnuoy/charms/trusty/nova-cloud-controller/disable-services-until-db-ready
Liam Young (community): Needs Resubmitting
James Page: Needs Fixing
Diff: 337 lines (+175/-7)
6 files modified
charm-helpers-hooks.yaml (+1/-0)
hooks/charmhelpers/contrib/peerstorage/__init__.py (+83/-0)
hooks/nova_cc_hooks.py (+34/-3)
hooks/nova_cc_utils.py (+34/-2)
unit_tests/test_nova_cc_hooks.py (+5/-0)
unit_tests/test_nova_cc_utils.py (+18/-2)
lp://staging/~gnuoy/charms/trusty/nova-cloud-controller/stable-230495
Revision history for this message
Andreas Hasenack (ahasenack) wrote :
Revision history for this message
James Page (james-page) wrote :

Andreas - can you check comment 4, 5, 6 in bug 1335139? db sync via charm could be a little fragile due to the lack of good leader election right now.

Revision history for this message
James Page (james-page) wrote :

Also are you running multiple service units? I'm assuming that you are.

Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote : Re: [Bug 1347245] Re: "nova-manage db sync" fails with IntegrityError, duplicate entry

FWIW when I saw this it was with a single service unit.

On 24 July 2014 21:38, James Page <email address hidden> wrote:
> Also are you running multiple service units? I'm assuming that you are.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1347245
>
> Title:
> "nova-manage db sync" fails with IntegrityError, duplicate entry
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/charms/+source/nova-cloud-controller/+bug/1347245/+subscriptions

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

No, it's a single unit of nova-cloud-controller. The only services that have multiple units are: storage (swift-storage or ceph) and compute.

Revision history for this message
James Page (james-page) wrote :

Think we have this one tracked down; the problem is that the nova-conductor process is running during the db sync operation; relation state is set prior to -changed being executed, and most changed hooks write out all files based on current state, so its possible for the nova-* services to be started and pointing and mysql prior to the db sync process being execute.

The solution for this in a single unit deployment is to stop/start the processes around the sync process; more complex in HA scenario.

Liam Young (gnuoy)
Changed in nova-cloud-controller (Juju Charms Collection):
assignee: nobody → Liam Young (gnuoy)
Liam Young (gnuoy)
Changed in nova-cloud-controller (Juju Charms Collection):
importance: Undecided → Medium
status: New → In Progress
Ryan Harper (raharper)
tags: added: oil
James Page (james-page)
Changed in nova-cloud-controller (Juju Charms Collection):
status: In Progress → Fix Committed
Revision history for this message
Björn Tillenius (bjornt) wrote :

Has this been backported to the stable branch? I ran into it again. Attaching the log file.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

This MP does not have a single +1, how come it be merged?
"""
    Liam Young: Resubmit on 2014-08-15
    James Page: Needs Fixing on 2014-08-15
"""

Revision history for this message
Liam Young (gnuoy) wrote :

Andreas, it was +1'd by James. It looks like explicitly stating the approval on lp was missed.

Revision history for this message
David Britton (dpb) wrote :

Hi Liam --

I tested this and it looks like you are missing a dependency on a new charmhelpers sync:

lp:~gnuoy/charms/trusty/nova-cloud-controller/stable-230495 

2014-10-03 17:22:37 INFO install File "/var/lib/juju/agents/unit-nova-cloud-controller-0/charm/hooks/install", line 44, in <module>
2014-10-03 17:22:37 INFO install from charmhelpers.contrib.peerstorage import (
2014-10-03 17:22:37 INFO install ImportError: No module named peerstorage

Changed in nova-cloud-controller (Juju Charms Collection):
status: Fix Committed → In Progress
Revision history for this message
David Britton (dpb) wrote :

Hi Liam -- I put this back to 'in progress' so we can better track it as not finished. If that causes problems for you, feel free to revert that.

Revision history for this message
Liam Young (gnuoy) wrote :

Urgh, yes, you're right. I've updated my the branch and retested

Edward Hope-Morley (hopem)
tags: added: openstack
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Retested here, no errors.

Edward Hope-Morley (hopem)
Changed in nova-cloud-controller (Juju Charms Collection):
status: In Progress → Fix Committed
James Page (james-page)
Changed in nova-cloud-controller (Juju Charms Collection):
milestone: none → 15.01
James Page (james-page)
Changed in nova-cloud-controller (Juju Charms Collection):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.