OpenStack Compute (nova)

SQL Errors on a fresh install

Bug #655171 reported by Chmouel Boudjnah on 2010-10-05

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Medium	Josh Kearney	OpenStack Compute (nova) 2011.1 "bexar"

Bug Description

I have just done a fresh install using the package from latest nova-core ppa :

chmouel@chmoutest:~$ dpkg-query --showformat='${Package}-${Version}\n' -W '*nova*'
nova-api-0.9.1~r325-0ubuntu0ppa1~lucid1
nova-common-0.9.1~r325-0ubuntu0ppa1~lucid1
nova-compute-0.9.1~r325-0ubuntu0ppa1~lucid1
nova-objectstore-0.9.1~r325-0ubuntu0ppa1~lucid1
nova-volume-0.9.1~r325-0ubuntu0ppa1~lucid1
python-nova-0.9.1~r325-0ubuntu0ppa1~lucid1

I am running those command on a fresh install :

nova-manage user admin ant
nova-manage project create antproj ant
nova-manage project zip antproj ant
unzip nova.zip

and this is what I am getting in the logs (there is two of them!), things seems to work still afterward :

nova-compute.log:

2010-10-05 15:32:53+0100 [-] (root): ERROR model server went away
2010-10-05 15:32:53+0100 [-] Traceback (most recent call last):
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state
2010-10-05 15:32:53+0100 [-] {'report_count': service_ref['report_count'] + 1})
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 109, in service_update
2010-10-05 15:32:53+0100 [-] return IMPL.service_update(context, service_id, values)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 92, in wrapper
2010-10-05 15:32:53+0100 [-] return f(*args, **kwargs)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 246, in service_update
2010-10-05 15:32:53+0100 [-] service_ref.save(session=session)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 66, in save
2010-10-05 15:32:53+0100 [-] session.flush()
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1359, in flush
2010-10-05 15:32:53+0100 [-] self._flush(objects)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1440, in _flush
2010-10-05 15:32:53+0100 [-] flush_context.execute()
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
2010-10-05 15:32:53+0100 [-] rec.execute(self)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
2010-10-05 15:32:53+0100 [-] uow
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1830, in _save_obj
2010-10-05 15:32:53+0100 [-] execute(statement, params)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
2010-10-05 15:32:53+0100 [-] params)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
2010-10-05 15:32:53+0100 [-] return self.__execute_context(context)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
2010-10-05 15:32:53+0100 [-] context.parameters[0], context=context)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
2010-10-05 15:32:53+0100 [-] context)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
2010-10-05 15:32:53+0100 [-] context)
2010-10-05 15:32:53+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
2010-10-05 15:32:53+0100 [-] cursor.execute(statement, parameters)
2010-10-05 15:32:53+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:32:48.272188', 5, 1)
2010-10-05 15:33:03+0100 [-] (root): ERROR Recovered model server connection!
2010-10-05 15:33:13+0100 [-] (root): ERROR model server went away
2010-10-05 15:33:13+0100 [-] Traceback (most recent call last):
2010-10-05 15:33:13+0100 [-] File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state

nova-volume.log:

2010-10-05 15:31:56+0100 [-] Traceback (most recent call last):
2010-10-05 15:31:56+0100 [-] File "/usr/bin/nova-volume", line 40, in <module>
2010-10-05 15:31:56+0100 [-] twistd.serve(__file__)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/twistd.py", line 273, in serve
2010-10-05 15:31:56+0100 [-] twistd.runApp(options)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
2010-10-05 15:31:56+0100 [-] _SomeApplicationRunner(config).run()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/application/app.py", line 423, in run
2010-10-05 15:31:56+0100 [-] self.postApplication()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/scripts/_twistd_unix.py", line 205, in postApplication
2010-10-05 15:31:56+0100 [-] self.startApplication(self.application)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/scripts/_twistd_unix.py", line 317, in startApplication
2010-10-05 15:31:56+0100 [-] app.startApplication(application, not self.config['no_save'])
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/application/app.py", line 713, in startApplication
2010-10-05 15:31:56+0100 [-] service.IService(application).startService()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/python2.6/dist-packages/twisted/application/service.py", line 278, in startService
2010-10-05 15:31:56+0100 [-] service.startService()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/service.py", line 69, in startService
2010-10-05 15:31:56+0100 [-] self.binary)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 95, in service_get_by_args
2010-10-05 15:31:56+0100 [-] return IMPL.service_get_by_args(context, host, binary)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/utils.py", line 195, in __getattr__
2010-10-05 15:31:56+0100 [-] backend = self.__get_backend()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/utils.py", line 190, in __get_backend
2010-10-05 15:31:56+0100 [-] self.__backend = __import__(name, None, None, fromlist)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/__init__.py", line 24, in <module>
2010-10-05 15:31:56+0100 [-] models.register_models()
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 469, in register_models
2010-10-05 15:31:56+0100 [-] model.metadata.create_all(engine)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/schema.py", line 2119, in create_all
2010-10-05 15:31:56+0100 [-] bind.create(self, checkfirst=checkfirst, tables=tables)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1701, in create
2010-10-05 15:31:56+0100 [-] connection=connection, **kwargs)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1743, in _run_visitor
2010-10-05 15:31:56+0100 [-] **kwargs).traverse_single(element)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/sql/visitors.py", line 77, in traverse_single
2010-10-05 15:31:56+0100 [-] return meth(obj, **kw)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/ddl.py", line 42, in visit_metadata
2010-10-05 15:31:56+0100 [-] self.traverse_single(table, create_ok=True)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/sql/visitors.py", line 77, in traverse_single
2010-10-05 15:31:56+0100 [-] return meth(obj, **kw)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/ddl.py", line 58, in visit_table
2010-10-05 15:31:56+0100 [-] self.connection.execute(schema.CreateTable(table))
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
2010-10-05 15:31:56+0100 [-] params)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1247, in _execute_ddl
2010-10-05 15:31:56+0100 [-] return self.__execute_context(context)
2010-10-05 15:31:56+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
...skipping...
2010-10-05 15:32:54+0100 [-] execute(statement, params)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
2010-10-05 15:32:54+0100 [-] params)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
2010-10-05 15:32:54+0100 [-] return self.__execute_context(context)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
2010-10-05 15:32:54+0100 [-] context.parameters[0], context=context)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
2010-10-05 15:32:54+0100 [-] context)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
2010-10-05 15:32:54+0100 [-] context)
2010-10-05 15:32:54+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
2010-10-05 15:32:54+0100 [-] cursor.execute(statement, parameters)
2010-10-05 15:32:54+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:32:49.582295', 5, 2)
2010-10-05 15:33:01+0100 [-] (root): ERROR Recovered model server connection!
2010-10-05 15:33:34+0100 [-] (root): ERROR model server went away
2010-10-05 15:33:34+0100 [-] Traceback (most recent call last):
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state
2010-10-05 15:33:34+0100 [-] {'report_count': service_ref['report_count'] + 1})
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 109, in service_update
2010-10-05 15:33:34+0100 [-] return IMPL.service_update(context, service_id, values)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 92, in wrapper
2010-10-05 15:33:34+0100 [-] return f(*args, **kwargs)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 246, in service_update
2010-10-05 15:33:34+0100 [-] service_ref.save(session=session)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 66, in save
2010-10-05 15:33:34+0100 [-] session.flush()
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1359, in flush
2010-10-05 15:33:34+0100 [-] self._flush(objects)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1440, in _flush
2010-10-05 15:33:34+0100 [-] flush_context.execute()
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
2010-10-05 15:33:34+0100 [-] rec.execute(self)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
2010-10-05 15:33:34+0100 [-] uow
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1830, in _save_obj
2010-10-05 15:33:34+0100 [-] execute(statement, params)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
2010-10-05 15:33:34+0100 [-] params)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
2010-10-05 15:33:34+0100 [-] return self.__execute_context(context)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
2010-10-05 15:33:34+0100 [-] context.parameters[0], context=context)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
2010-10-05 15:33:34+0100 [-] context)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
2010-10-05 15:33:34+0100 [-] context)
2010-10-05 15:33:34+0100 [-] File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
2010-10-05 15:33:34+0100 [-] cursor.execute(statement, parameters)
2010-10-05 15:33:34+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:33:29.616427', 8, 2)

Revision history for this message

Chmouel Boudjnah (chmouel) wrote on 2010-10-05:

let me know if you want me to copy those logs in somewhere more readable!

Revision history for this message

Soren Hansen (soren) wrote on 2010-10-05:

This is very likely a duplicate of bug 654452.

Revision history for this message

Jay Pipes (jaypipes) wrote on 2010-10-06:

Hi Chmouel!

Could you pull a fresh trunk copy of Nova and verify that the fix for bug 654452 indeed fixed this issue for you? Thanks!

-jay

Changed in nova:
status:	New → Incomplete
importance:	Undecided → Medium

Revision history for this message

Chmouel Boudjnah (chmouel) wrote on 2010-10-06:

Hey Jay,

I have just installed the latest packages :

chmouel@chmoutest:/var/log/nova$ dpkg-query --showformat='${Package}-${Version}\n' -W '*nova*'
nova-api-0.9.1~r331-0ubuntu0ppa1~lucid1
nova-common-0.9.1~r331-0ubuntu0ppa1~lucid1
nova-compute-0.9.1~r331-0ubuntu0ppa1~lucid1
nova-objectstore-0.9.1~r331-0ubuntu0ppa1~lucid1
nova-volume-0.9.1~r331-0ubuntu0ppa1~lucid1
python-nova-0.9.1~r331-0ubuntu0ppa1~lucid1

(I believe #654452 was fixed in r322 so should be applied)

And I am getting the same error :

nova-volume.log :

http://is.gd/fNMcg

nova-compute.log

http://is.gd/fNMee

Chmouel.

Revision history for this message

Chmouel Boudjnah (chmouel) wrote on 2010-10-06:

Just to clarify everything was reinstalled from scratch.

Revision history for this message

Jay Pipes (jaypipes) wrote on 2010-10-06:

Thanks for the follow-up Chmouel! Setting to Confirmed. We'll get someone looking into this. :)

Changed in nova:
status:	Incomplete → Confirmed

Revision history for this message

Vish Ishaya (vishvananda) wrote on 2010-10-07: Re: [Bug 655171] Re: SQL Errors on a fresh install

Download full text (14.1 KiB)

Sqlite locks the database and doesn't support dealing with threads that well. That said, if you can put up with an occasional error with the services failing to update, it seems to run fine. Perhaps we could specifically check for locked database in the services update call and just print a warning instead of an error.

On Oct 6, 2010, at 7:31 AM, Jay Pipes wrote:

Sqlite locks the database and doesn't support dealing with threads that well.  That said, if you can put up with an occasional error with the services failing to update, it seems to run fine.  Perhaps we could specifically check for locked database in the services update call and just print a warning instead of an error.

On Oct 6, 2010, at 7:31 AM, Jay Pipes wrote:

> Thanks for the follow-up Chmouel!  Setting to Confirmed.  We'll get
> someone looking into this. :)
> 
> ** Changed in: nova
>       Status: Incomplete => Confirmed
> 
> -- 
> SQL Errors on a fresh install
> https://bugs.launchpad.net/bugs/655171
> You received this bug notification because you are a member of Nova
> Bugs, which is subscribed to OpenStack Compute (nova).
> 
> Status in OpenStack Compute (Nova): Confirmed
> 
> Bug description:
> 
> I have just done a fresh install using the package from latest nova-core ppa :
> 
> chmouel@chmoutest:~$ dpkg-query --showformat='${Package}-${Version}\n' -W '*nova*'
> nova-api-0.9.1~r325-0ubuntu0ppa1~lucid1
> nova-common-0.9.1~r325-0ubuntu0ppa1~lucid1
> nova-compute-0.9.1~r325-0ubuntu0ppa1~lucid1
> nova-objectstore-0.9.1~r325-0ubuntu0ppa1~lucid1
> nova-volume-0.9.1~r325-0ubuntu0ppa1~lucid1
> python-nova-0.9.1~r325-0ubuntu0ppa1~lucid1
> 
> I am running those command on a fresh install :
> 
> nova-manage user admin ant
> nova-manage project create antproj ant
> nova-manage project zip antproj ant
> unzip nova.zip
> 
> and this is what I am getting in the logs (there is two of them!), things seems to work still afterward :
> 
> nova-compute.log:
> 
> 2010-10-05 15:32:53+0100 [-] (root): ERROR model server went away
> 2010-10-05 15:32:53+0100 [-] Traceback (most recent call last):
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state
> 2010-10-05 15:32:53+0100 [-]     {'report_count': service_ref['report_count'] + 1})
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 109, in service_update
> 2010-10-05 15:32:53+0100 [-]     return IMPL.service_update(context, service_id, values)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 92, in wrapper
> 2010-10-05 15:32:53+0100 [-]     return f(*args, **kwargs)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 246, in service_update
> 2010-10-05 15:32:53+0100 [-]     service_ref.save(session=session)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 66, in save
> 2010-10-05 15:32:53+0100 [-]     session.flush()
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1359, in flush
> 2010-10-05 15:32:53+0100 [-]     self._flush(objects)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1440, in _flush
> 2010-10-05 15:32:53+0100 [-]     flush_context.execute()
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
> 2010-10-05 15:32:53+0100 [-]     rec.execute(self)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
> 2010-10-05 15:32:53+0100 [-]     uow
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1830, in _save_obj
> 2010-10-05 15:32:53+0100 [-]     execute(statement, params)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
> 2010-10-05 15:32:53+0100 [-]     params)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
> 2010-10-05 15:32:53+0100 [-]     return self.__execute_context(context)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
> 2010-10-05 15:32:53+0100 [-]     context.parameters[0], context=context)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
> 2010-10-05 15:32:53+0100 [-]     context)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
> 2010-10-05 15:32:53+0100 [-]     context)
> 2010-10-05 15:32:53+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
> 2010-10-05 15:32:53+0100 [-]     cursor.execute(statement, parameters)
> 2010-10-05 15:32:53+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:32:48.272188', 5, 1)
> 2010-10-05 15:33:03+0100 [-] (root): ERROR Recovered model server connection!
> 2010-10-05 15:33:13+0100 [-] (root): ERROR model server went away
> 2010-10-05 15:33:13+0100 [-] Traceback (most recent call last):
> 2010-10-05 15:33:13+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state
> 
> nova-volume.log:
> 
> 2010-10-05 15:31:56+0100 [-] Traceback (most recent call last):
> 2010-10-05 15:31:56+0100 [-]   File "/usr/bin/nova-volume", line 40, in <module>
> 2010-10-05 15:31:56+0100 [-]     twistd.serve(__file__)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/twistd.py", line 273, in serve
> 2010-10-05 15:31:56+0100 [-]     twistd.runApp(options)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
> 2010-10-05 15:31:56+0100 [-]     _SomeApplicationRunner(config).run()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/application/app.py", line 423, in run
> 2010-10-05 15:31:56+0100 [-]     self.postApplication()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/scripts/_twistd_unix.py", line 205, in postApplication
> 2010-10-05 15:31:56+0100 [-]     self.startApplication(self.application)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/scripts/_twistd_unix.py", line 317, in startApplication
> 2010-10-05 15:31:56+0100 [-]     app.startApplication(application, not self.config['no_save'])
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/application/app.py", line 713, in startApplication
> 2010-10-05 15:31:56+0100 [-]     service.IService(application).startService()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/python2.6/dist-packages/twisted/application/service.py", line 278, in startService
> 2010-10-05 15:31:56+0100 [-]     service.startService()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/service.py", line 69, in startService
> 2010-10-05 15:31:56+0100 [-]     self.binary)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 95, in service_get_by_args
> 2010-10-05 15:31:56+0100 [-]     return IMPL.service_get_by_args(context, host, binary)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/utils.py", line 195, in __getattr__
> 2010-10-05 15:31:56+0100 [-]     backend = self.__get_backend()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/utils.py", line 190, in __get_backend
> 2010-10-05 15:31:56+0100 [-]     self.__backend = __import__(name, None, None, fromlist)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/__init__.py", line 24, in <module>
> 2010-10-05 15:31:56+0100 [-]     models.register_models()
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 469, in register_models
> 2010-10-05 15:31:56+0100 [-]     model.metadata.create_all(engine)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/schema.py", line 2119, in create_all
> 2010-10-05 15:31:56+0100 [-]     bind.create(self, checkfirst=checkfirst, tables=tables)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1701, in create
> 2010-10-05 15:31:56+0100 [-]     connection=connection, **kwargs)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1743, in _run_visitor
> 2010-10-05 15:31:56+0100 [-]     **kwargs).traverse_single(element)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/sql/visitors.py", line 77, in traverse_single
> 2010-10-05 15:31:56+0100 [-]     return meth(obj, **kw)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/ddl.py", line 42, in visit_metadata
> 2010-10-05 15:31:56+0100 [-]     self.traverse_single(table, create_ok=True)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/sql/visitors.py", line 77, in traverse_single
> 2010-10-05 15:31:56+0100 [-]     return meth(obj, **kw)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/ddl.py", line 58, in visit_table
> 2010-10-05 15:31:56+0100 [-]     self.connection.execute(schema.CreateTable(table))
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
> 2010-10-05 15:31:56+0100 [-]     params)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1247, in _execute_ddl
> 2010-10-05 15:31:56+0100 [-]     return self.__execute_context(context)
> 2010-10-05 15:31:56+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
> ...skipping...
> 2010-10-05 15:32:54+0100 [-]     execute(statement, params)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
> 2010-10-05 15:32:54+0100 [-]     params)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
> 2010-10-05 15:32:54+0100 [-]     return self.__execute_context(context)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
> 2010-10-05 15:32:54+0100 [-]     context.parameters[0], context=context)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
> 2010-10-05 15:32:54+0100 [-]     context)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
> 2010-10-05 15:32:54+0100 [-]     context)
> 2010-10-05 15:32:54+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
> 2010-10-05 15:32:54+0100 [-]     cursor.execute(statement, parameters)
> 2010-10-05 15:32:54+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:32:49.582295', 5, 2)
> 2010-10-05 15:33:01+0100 [-] (root): ERROR Recovered model server connection!
> 2010-10-05 15:33:34+0100 [-] (root): ERROR model server went away
> 2010-10-05 15:33:34+0100 [-] Traceback (most recent call last):
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/service.py", line 171, in report_state
> 2010-10-05 15:33:34+0100 [-]     {'report_count': service_ref['report_count'] + 1})
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 109, in service_update
> 2010-10-05 15:33:34+0100 [-]     return IMPL.service_update(context, service_id, values)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 92, in wrapper
> 2010-10-05 15:33:34+0100 [-]     return f(*args, **kwargs)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 246, in service_update
> 2010-10-05 15:33:34+0100 [-]     service_ref.save(session=session)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/models.py", line 66, in save
> 2010-10-05 15:33:34+0100 [-]     session.flush()
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1359, in flush
> 2010-10-05 15:33:34+0100 [-]     self._flush(objects)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1440, in _flush
> 2010-10-05 15:33:34+0100 [-]     flush_context.execute()
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
> 2010-10-05 15:33:34+0100 [-]     rec.execute(self)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
> 2010-10-05 15:33:34+0100 [-]     uow
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1830, in _save_obj
> 2010-10-05 15:33:34+0100 [-]     execute(statement, params)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1194, in execute
> 2010-10-05 15:33:34+0100 [-]     params)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1274, in _execute_clauseelement
> 2010-10-05 15:33:34+0100 [-]     return self.__execute_context(context)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1305, in __execute_context
> 2010-10-05 15:33:34+0100 [-]     context.parameters[0], context=context)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
> 2010-10-05 15:33:34+0100 [-]     context)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
> 2010-10-05 15:33:34+0100 [-]     context)
> 2010-10-05 15:33:34+0100 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 299, in do_execute
> 2010-10-05 15:33:34+0100 [-]     cursor.execute(statement, parameters)
> 2010-10-05 15:33:34+0100 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-05 14:33:29.616427', 8, 2)
> 
>

Revision history for this message

Chmouel Boudjnah (chmouel) wrote on 2010-10-07:

On 7 October 2010 09:12, vishvananda <email address hidden> wrote:

> Sqlite locks the database and doesn't support dealing with threads that
> well. That said, if you can put up with an occasional error with the
> services failing to update, it seems to run fine. Perhaps we could
> specifically check for locked database in the services update call and
> just print a warning instead of an error.

Why don't we add check_same_thread=False to sqlite.connect ? swift team took
a lot of time to tackle the sqlite locking problem (and others) maybe we can
learn from them ?

Chmouel.

Josh Kearney (jk0) on 2010-11-23

Changed in nova:
status:	Confirmed → In Progress
assignee:	nobody → Josh Kearney (jk0)

Josh Kearney (jk0) on 2010-11-23

Changed in nova:
status:	In Progress → Fix Committed

Thierry Carrez (ttx) on 2011-02-07

Changed in nova:
milestone:	none → 2011.1
status:	Fix Committed → Fix Released

Revision history for this message

Vitaly Yevstigneyev (asmaral71) wrote on 2015-06-26:

I have encountered the same problem while running 'su -s /bin/sh -c "nova-manage db sync" nova' during the first install of Nova in Kilo. Deleting the '/var/lib/nova/nova.sqlite' file helped the problem.
It seems like the word "can" in phrase "you can delete the /var/lib/nova/nova.sqlite file" in installation guide should be replaced with "must".

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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