nova team mailing list archive

Thread
Date

Database is locked

To: <nova@xxxxxxxxxxxxxxxxxxx>
From: <masumotok@xxxxxxxxxxxxx>
Date: Mon, 25 Oct 2010 13:33:52 +0900
Accept-language: ja-JP
Acceptlanguage: ja-JP
Thread-index: Actz/dpc/uEGkiFYSeuYJFiFqGRzKQ==
Thread-topic: Database is locked

Hello, 

Now I'm checking Austine Release version of nova.
And I encounter the below problem. 

Problem: when I tries to euca-run-instance -t m1.small -k testkey ami-tiny,
  Nova-scheduler issued an error "Database is locked"(attached).
  Few seconds later, nova-compute issued an same error(also attached).
   
  After I checked the behavior, about both cnova-compute and nova-scheduler,
  nova.service.report_state cause this problem. Also, additional information
  is that, in case of scheduler, calling reporting_state got successful twice/
  3rd just after euca-run-instance.

My next plan is using MySQL instead of sqlite, b/c
this "Database is locked" error seems like typical sqlite error.
But if someone knows solution for it, please let me know.

Thanks in advance,
Kei Masumoto

------------------------------------------------------------------
Kei Masumoto <masumotok@xxxxxxxxxxxxx>
Assistant Manager,
Research and Development Hq, NTTData Corp.
tel: +81 50 5546 2301 FAX: +81 3 3532 0491


DEBUG:root:Running cmd: parted --script /opt/nova-2010.1/nova/../instances/instance-3789518487/disk mkpartfs primary ext2 20971583s 62914622s
2010-10-24 07:39:40+0900 [-] (root): DEBUG Running cmd: parted --script /opt/nova-2010.1/nova/../instances/instance-3789518487/disk mkpartfs primary ext2 20971583s 62914622s
DEBUG:root:Running cmd: dd if=/opt/nova-2010.1/nova/../instances/instance-3789518487/disk-raw of=/opt/nova-2010.1/nova/../instances/instance-3789518487/disk bs=512 seek=63 conv=notrunc,fsync
2010-10-24 07:39:46+0900 [-] (root): DEBUG Running cmd: dd if=/opt/nova-2010.1/nova/../instances/instance-3789518487/disk-raw of=/opt/nova-2010.1/nova/../instances/instance-3789518487/disk bs=512 seek=63 conv=notrunc,fsync
ERROR:root:model server went away
Traceback (most recent call last):
  File "/opt/nova-2010.1/nova/service.py", line 178, in report_state
    {'report_count': service_ref['report_count'] + 1})
  File "/opt/nova-2010.1/nova/db/api.py", line 109, in service_update
    return IMPL.service_update(context, service_id, values)
  File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 98, in wrapper
    return f(*args, **kwargs)
  File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 252, in service_update
    service_ref.save(session=session)
  File "/opt/nova-2010.1/nova/db/sqlalchemy/models.py", line 66, in save
    session.flush()
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1346, in flush
    self._flush(objects)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1427, in _flush
    flush_context.execute()
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
    rec.execute(self)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
    uow
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1800, in _save_obj
    execute(statement, params)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1157, in execute
    params)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
    return self.__execute_context(context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1268, in __execute_context
    context.parameters[0], context=context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
    context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
    context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 288, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-23 22:40:41.095193', 287, 1)
2010-10-24 07:40:46+0900 [-] (root): ERROR model server went away
2010-10-24 07:40:46+0900 [-] Traceback (most recent call last):
2010-10-24 07:40:46+0900 [-]   File "/opt/nova-2010.1/nova/service.py", line 178, in report_state
2010-10-24 07:40:46+0900 [-]     {'report_count': service_ref['report_count'] + 1})
2010-10-24 07:40:46+0900 [-]   File "/opt/nova-2010.1/nova/db/api.py", line 109, in service_update
2010-10-24 07:40:46+0900 [-]     return IMPL.service_update(context, service_id, values)
2010-10-24 07:40:46+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 98, in wrapper
2010-10-24 07:40:46+0900 [-]     return f(*args, **kwargs)
2010-10-24 07:40:46+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 252, in service_update
2010-10-24 07:40:46+0900 [-]     service_ref.save(session=session)
2010-10-24 07:40:46+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/models.py", line 66, in save
2010-10-24 07:40:46+0900 [-]     session.flush()
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1346, in flush
2010-10-24 07:40:46+0900 [-]     self._flush(objects)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1427, in _flush
2010-10-24 07:40:46+0900 [-]     flush_context.execute()
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
2010-10-24 07:40:46+0900 [-]     rec.execute(self)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
2010-10-24 07:40:46+0900 [-]     uow
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1800, in _save_obj
2010-10-24 07:40:46+0900 [-]     execute(statement, params)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1157, in execute
2010-10-24 07:40:46+0900 [-]     params)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
2010-10-24 07:40:46+0900 [-]     return self.__execute_context(context)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1268, in __execute_context
2010-10-24 07:40:46+0900 [-]     context.parameters[0], context=context)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
2010-10-24 07:40:46+0900 [-]     context)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
2010-10-24 07:40:46+0900 [-]     context)
2010-10-24 07:40:46+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 288, in do_execute
2010-10-24 07:40:46+0900 [-]     cursor.execute(statement, parameters)
2010-10-24 07:40:46+0900 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-23 22:40:41.095193', 287, 1)
libvir: Network Filtererror : internal error Could not get access to ACL tech driver 'ebiptables'
ERROR:root:instance instance-3789518487: Failed to spawn
Traceback (most recent call last):
  File "/opt/nova-2010.1/nova/compute/manager.py", line 92, in run_instance
    yield self.driver.spawn(instance_ref)
  File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 823, in _inlineCallbacks
    result = g.send(result)
  File "/opt/nova-2010.1/nova/virt/libvirt_conn.py", line 234, in spawn
    yield self._conn.createXML(xml, 0)
  File "/usr/lib/python2.6/dist-packages/libvirt.py", line 1289, in createXML
    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
libvirtError: internal error Could not get access to ACL tech driver 'ebiptables'
2010-10-24 07:40:57+0900 [-] (root): ERROR instance instance-3789518487: Failed to spawn
2010-10-24 07:40:57+0900 [-] Traceback (most recent call last):
2010-10-24 07:40:57+0900 [-]   File "/opt/nova-2010.1/nova/compute/manager.py", line 92, in run_instance
2010-10-24 07:40:57+0900 [-]     yield self.driver.spawn(instance_ref)
2010-10-24 07:40:57+0900 [-]   File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 823, in _inlineCallbacks
2010-10-24 07:40:57+0900 [-]     result = g.send(result)
2010-10-24 07:40:57+0900 [-]   File "/opt/nova-2010.1/nova/virt/libvirt_conn.py", line 234, in spawn
2010-10-24 07:40:57+0900 [-]     yield self._conn.createXML(xml, 0)
2010-10-24 07:40:57+0900 [-]   File "/usr/lib/python2.6/dist-packages/libvirt.py", line 1289, in createXML
2010-10-24 07:40:57+0900 [-]     if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
2010-10-24 07:40:57+0900 [-] libvirtError: internal error Could not get access to ACL tech driver 'ebiptables'
libvir: QEMU error : Domain not found: no domain with matching name 'instance-3789518487'
2010-10-24 07:40:57+0900 [-] Unhandled error in Deferred:
2010-10-24 07:40:57+0900 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 307, in errback
            self._startRunCallbacks(fail)
          File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 354, in _startRunCallbacks
            self._runCallbacks()
          File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 371, in _runCallbacks
            self.result = callback(self.result, *args, **kw)
          File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 879, in gotResult
            _inlineCallbacks(r, g, deferred)
        --- <exception caught here> ---
          File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 821, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python2.6/dist-packages/twisted/python/failure.py", line 338, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/opt/nova-2010.1/nova/compute/manager.py", line 104, in run_instance
            self._update_state(context, instance_id)
          File "/opt/nova-2010.1/nova/compute/manager.py", line 62, in _update_state
            state = self.driver.get_info(instance_ref.name)['state']
          File "/opt/nova-2010.1/nova/virt/libvirt_conn.py", line 401, in get_info
            virt_dom = self._conn.lookupByName(instance_name)
          File "/usr/lib/python2.6/dist-packages/libvirt.py", line 1442, in lookupByName
            if ret is None:raise libvirtError('virDomainLookupByName() failed', conn=self)
        libvirt.libvirtError: Domain not found: no domain with matching name 'instance-3789518487'

ERROR:root:Recovered model server connection!
2010-10-24 07:40:58+0900 [-] (root): ERROR Recovered model server connection!

scheduler


2010-10-24 07:13:05+0900 [-] (root): ERROR model server went away
2010-10-24 07:13:05+0900 [-] Traceback (most recent call last):
2010-10-24 07:13:05+0900 [-]   File "/opt/nova-2010.1/nova/service.py", line 178, in report_state
2010-10-24 07:13:05+0900 [-]     {'report_count': service_ref['report_count'] + 1})
2010-10-24 07:13:05+0900 [-]   File "/opt/nova-2010.1/nova/db/api.py", line 109, in service_update
2010-10-24 07:13:05+0900 [-]     return IMPL.service_update(context, service_id, values)
2010-10-24 07:13:05+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 98, in wrapper
2010-10-24 07:13:05+0900 [-]     return f(*args, **kwargs)
2010-10-24 07:13:05+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/api.py", line 252, in service_update
2010-10-24 07:13:05+0900 [-]     service_ref.save(session=session)
2010-10-24 07:13:05+0900 [-]   File "/opt/nova-2010.1/nova/db/sqlalchemy/models.py", line 66, in save
2010-10-24 07:13:05+0900 [-]     session.flush()
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1346, in flush
2010-10-24 07:13:05+0900 [-]     self._flush(objects)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 1427, in _flush
2010-10-24 07:13:05+0900 [-]     flush_context.execute()
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 299, in execute
2010-10-24 07:13:05+0900 [-]     rec.execute(self)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/unitofwork.py", line 443, in execute
2010-10-24 07:13:05+0900 [-]     uow
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/mapper.py", line 1800, in _save_obj
2010-10-24 07:13:05+0900 [-]     execute(statement, params)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1157, in execute
2010-10-24 07:13:05+0900 [-]     params)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
2010-10-24 07:13:05+0900 [-]     return self.__execute_context(context)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1268, in __execute_context
2010-10-24 07:13:05+0900 [-]     context.parameters[0], context=context)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
2010-10-24 07:13:05+0900 [-]     context)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
2010-10-24 07:13:05+0900 [-]     context)
2010-10-24 07:13:05+0900 [-]   File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 288, in do_execute
2010-10-24 07:13:05+0900 [-]     cursor.execute(statement, parameters)
2010-10-24 07:13:05+0900 [-] OperationalError: (OperationalError) database is locked u'UPDATE services SET updated_at=?, report_count=? WHERE services.id = ?' ('2010-10-23 22:13:00.522920', 130, 3)
ERROR:root:Recovered model server connection!
2010-10-24 07:13:51+0900 [-] (root): ERROR Recovered model server connection!

Follow ups

Re: Database is locked
From: Andy Smith, 2010-10-25