OperationalError: database is locked after 11.2-RELEASE upgrade (31f889bbf)

181228

Dabbler
Joined
Dec 28, 2018
Messages
18
I have a Z2 pool on a box that has been running FreeNAS for several years. I attempted to upgrade from 9.10.2-U6 which was a regrettable decision. I have just had no luck getting 11.2-RELEASE to work.

In the past week I've performed at least 6 installs using 9.10.2-U6, 11.1 and 11.2 trying to sort through some of the problems with 11.2. I've confirmed that the same hardware setup works with 9.10.x and 11.1 but just will not work with 11.2. These observations seem to refute the hypothesis that potentially 'defective' USB stick hardware rather than software is responsible for the problem. (Yes, I'm still using USB sticks for boot devices, and all of the USB drives were fully benchmarked and tested for read/write prior to deployment.)

I've just completed a bare metal install of 11.2 so that I can get an accurate list of problems. Things seem to have worked flawlessly during the basic install, but things went bad on rebooting from the 11.2-U1 update. Following the upgrade I used "System > Upgrade > Verify Install" to confirm that all of the files were properly installed. Nonetheless I'm now suffering the following errors:

1. django.db.utils.OperationalError: database is locked

2. a long list of django errors went scrolling by on the terminal.

3. the GUI issued a Traceback for the environment following the upgrade:

Code:
Request Method:      POST    
Request URL:      http://xxx.xxx.xxx.xxx/legacy/system/update/check/?uuid=6e3ed455dff0409597356db6080c2d14    
Software Version:      FreeNAS-11.2-RELEASE (31f889bbf)    
Exception Type:      OperationalError    
Exception Value:      database is locked
Exception Location:      ./freenasUI/freeadmin/sqlite3_ha/base.py in locked_retry, line 389    
Server time:      Fri, 28 Dec 2018 18:37:49 -0800


And a window appears below that with the following text:

Code:
Environment:

Software Version: FreeNAS-11.2-RELEASE (31f889bbf)
Request Method: POST
Request URL: http://xxx.xxx.xxx.xxx/legacy/system/update/check/?uuid=6e3ed455dff0409597356db6080c2d14


Traceback:
File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in execute
  412.         execute = self.locked_retry(Database.Cursor.execute, query, params)
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in locked_retry
  403.                     raise e
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in locked_retry
  389.                 rv = method(self, *args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/django/core/handlers/exception.py" in inner
  42.             response = get_response(request)
File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py" in _legacy_get_response
  249.             response = self._get_response(request)
File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py" in _get_response
  178.             response = middleware_method(request, callback, callback_args, callback_kwargs)
File "./freenasUI/freeadmin/middleware.py" in process_view
  163.         return login_required(view_func)(request, *view_args, **view_kwargs)
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/decorators.py" in _wrapped_view
  22.             if test_func(request.user):
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/decorators.py" in <lambda>
  46.         lambda u: u.is_authenticated,
File "/usr/local/lib/python3.6/site-packages/django/utils/functional.py" in inner
  234.             self._setup()
File "/usr/local/lib/python3.6/site-packages/django/utils/functional.py" in _setup
  380.         self._wrapped = self._setupfunc()
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/middleware.py" in <lambda>
  24.         request.user = SimpleLazyObject(lambda: get_user(request))
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/middleware.py" in get_user
  12.         request._cached_user = auth.get_user(request)
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/__init__.py" in get_user
  187.             user = backend.get_user(user_id)
File "/usr/local/lib/python3.6/site-packages/django/contrib/auth/backends.py" in get_user
  102.             user = UserModel._default_manager.get(pk=user_id)
File "/usr/local/lib/python3.6/site-packages/django/db/models/manager.py" in manager_method
  85.                 return getattr(self.get_queryset(), name)(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py" in get
  379.         num = len(clone)
File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py" in __len__
  238.         self._fetch_all()
File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py" in _fetch_all
  1087.             self._result_cache = list(self.iterator())
File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py" in __iter__
  54.         results = compiler.execute_sql()
File "/usr/local/lib/python3.6/site-packages/django/db/models/sql/compiler.py" in execute_sql
  835.             cursor.execute(sql, params)
File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)
File "/usr/local/lib/python3.6/site-packages/django/db/utils.py" in __exit__
  94.                 six.reraise(dj_exc_type, dj_exc_value, traceback)
File "/usr/local/lib/python3.6/site-packages/django/utils/six.py" in reraise
  685.             raise value.with_traceback(tb)
File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in execute
  412.         execute = self.locked_retry(Database.Cursor.execute, query, params)
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in locked_retry
  403.                     raise e
File "./freenasUI/freeadmin/sqlite3_ha/base.py" in locked_retry
  389.                 rv = method(self, *args, **kwargs)

Exception Type: OperationalError at /legacy/system/update/check/
Exception Value: database is locked
 

181228

Dabbler
Joined
Dec 28, 2018
Messages
18
Interesting tidbit from the django documentation:

QUOTE:
SQLite is meant to be a lightweight database, and thus can't support a high level of concurrency. OperationalError: database is locked errors indicate that your application is experiencing more concurrency than sqlite can handle in default configuration. This error means that one thread or process has an exclusive lock on the database connection and another thread timed out waiting for the lock the be released.

Python's SQLite wrapper has a default timeout value that determines how long the second thread is allowed to wait on the lock before it times out and raises the OperationalError: database is locked error.

If you're getting this error, you can solve it by:

Switching to another database backend. At a certain point SQLite becomes too "lite" for real-world applications, and these sorts of concurrency errors indicate you've reached that point.

Rewriting your code to reduce concurrency and ensure that database transactions are short-lived.

Increase the default timeout value by setting the timeout database option​

Link:
https://docs.djangoproject.com/en/dev/ref/databases/#database-is-locked-errorsoption
 

181228

Dabbler
Joined
Dec 28, 2018
Messages
18
Update:

The database lockups went away with a reboot... lulling me into thinking that the problem was just a temporary upgrade glitch...

So I started populating my zpool with data, and within 24 hours I am getting database lockup advisories in my email inbox. It looks like the system is so unstable that a cascade of failures is occurring when the system tries to check volume status! Yikes!

New alerts: * Unable to run alert source 'VolumeStatus' Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) sqlite3.OperationalError: database is locked The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/alert.py", line 358, in __run_source alerts = (await alert_source.check()) or [] File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/../alert/source/volume_status.py", line 15, in check for pool in await self.middleware.call("pool.query"): File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1049, in _call return await methodobj(*args) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 664, in nf return await f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/service.py", line 266, in query 'datastore.query', self._config.datastore, [], datastore_options File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1063, in _call return await run_method(methodobj, *args) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1009, in run_in_thread return await self.loop.run_in_executor(executor, functools.partial(method, *args, **kwargs)) File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run result = self.fn(*self.args, **self.kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 668, in nf return f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 175, in query select=options.get('select'), File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 88, in __queryset_serialize for i in qs: File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 256, in __iter__ self._fetch_all() File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 1087, in _fetch_all self._result_cache = list(self.iterator()) File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 54, in __iter__ results = compiler.execute_sql() File "/usr/local/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 835, in execute_sql cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/utils.py", line 94, in __exit__ six.reraise(dj_exc_type, dj_exc_value, traceback) File "/usr/local/lib/python3.6/site-packages/django/utils/six.py", line 685, in reraise raise value.with_traceback(tb) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) django.db.utils.OperationalError: database is locked Alerts: * Unable to run alert source 'VolumeStatus' Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) sqlite3.OperationalError: database is locked The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/alert.py", line 358, in __run_source alerts = (await alert_source.check()) or [] File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/../alert/source/volume_status.py", line 15, in check for pool in await self.middleware.call("pool.query"): File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1049, in _call return await methodobj(*args) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 664, in nf return await f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/service.py", line 266, in query 'datastore.query', self._config.datastore, [], datastore_options File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1063, in _call return await run_method(methodobj, *args) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1009, in run_in_thread return await self.loop.run_in_executor(executor, functools.partial(method, *args, **kwargs)) File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run result = self.fn(*self.args, **self.kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 668, in nf return f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 175, in query select=options.get('select'), File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 88, in __queryset_serialize for i in qs: File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 256, in __iter__ self._fetch_all() File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 1087, in _fetch_all self._result_cache = list(self.iterator()) File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 54, in __iter__ results = compiler.execute_sql() File "/usr/local/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 835, in execute_sql cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/utils.py", line 94, in __exit__ six.reraise(dj_exc_type, dj_exc_value, traceback) File "/usr/local/lib/python3.6/site-packages/django/utils/six.py", line 685, in reraise raise value.with_traceback(tb) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) django.db.utils.OperationalError: database is locked

Gone alerts: * Unable to run alert source 'VolumeStatus' Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) sqlite3.OperationalError: database is locked The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/alert.py", line 358, in __run_source alerts = (await alert_source.check()) or [] File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/../alert/source/volume_status.py", line 15, in check for pool in await self.middleware.call("pool.query"): File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1049, in _call return await methodobj(*args) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 664, in nf return await f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/service.py", line 266, in query 'datastore.query', self._config.datastore, [], datastore_options File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1113, in call return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1063, in _call return await run_method(methodobj, *args) File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1009, in run_in_thread return await self.loop.run_in_executor(executor, functools.partial(method, *args, **kwargs)) File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run result = self.fn(*self.args, **self.kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 668, in nf return f(*args, **kwargs) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 175, in query select=options.get('select'), File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/datastore.py", line 88, in __queryset_serialize for i in qs: File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 256, in __iter__ self._fetch_all() File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 1087, in _fetch_all self._result_cache = list(self.iterator()) File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 54, in __iter__ results = compiler.execute_sql() File "/usr/local/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 835, in execute_sql cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/lib/python3.6/site-packages/django/db/utils.py", line 94, in __exit__ six.reraise(dj_exc_type, dj_exc_value, traceback) File "/usr/local/lib/python3.6/site-packages/django/utils/six.py", line 685, in reraise raise value.with_traceback(tb) File "/usr/local/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 412, in execute execute = self.locked_retry(Database.Cursor.execute, query, params) File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 403, in locked_retry raise e File "/usr/local/www/freenasUI/freeadmin/sqlite3_ha/base.py", line 389, in locked_retry rv = method(self, *args, **kwargs) django.db.utils.OperationalError: database is locked

Time to wipe this garbage off of my system and use a platform that doesn't place my data at risk. Sorry, but this is just unacceptable.
 
Last edited:

Spearfoot

He of the long foot
Moderator
Joined
May 13, 2015
Messages
2,478
Update:

The database lockups went away with a reboot... lulling me into thinking that the problem was just a temporary upgrade glitch...

So I started populating my zpool with data, and within 24 hours I am getting database lockup advisories in my email inbox. It looks like the system is so unstable that a cascade of failures is occurring when the system tries to check volume status! Yikes!



Time to wipe this garbage off of my system and use a platform that doesn't place my data at risk. Sorry, but this is just unacceptable.
Yikes!

I understand your frustration... I suggest you run 11.1-U6, which seems to be the most stable version of FreeNAS at the moment. Perhaps in six months or a year the rough edges will have been filed off of 11.2 and it will be usable.
 
Joined
Jan 4, 2014
Messages
1,644

Tovo

Cadet
Joined
Oct 25, 2018
Messages
8
Hi,
I'm facing to the same issue with a fresh re-installed FreeNAS-11.2-U4.1.
 
Top