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)
> 
>