OperationalError: (sqlite3.OperationalError) database is locked #2205
Description
I run FlexGet on a seedbox server to do some automatic downloads. This error constantly occurred on the server.
Below is one of the crash reports with SQLAlchemy debug logging enabled:
1 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 COMMIT
2 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Connection <sqlite3.Connection object at 0x7fe4548293d0> being returned to pool
3 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Connection <sqlite3.Connection object at 0x7fe4548293d0> rollback-on-return
4 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Closing connection <sqlite3.Connection object at 0x7fe4548293d0>
5 2018-09-05 03:00 DEBUG util.simple_persistence task1 Flushing simple persistence for task None to db.
6 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Created new connection <sqlite3.Connection object at 0x7fe454829ce0>
7 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Connection <sqlite3.Connection object at 0x7fe454829ce0> checked out from pool
8 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 BEGIN (implicit)
9 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 UPDATE simple_persistence SET json=? WHERE simple_persistence.feed IS NULL AND simple_persistence.plugin = ? AND simple_persistence."key" = ?
10 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 ('"2018-09-04T00:03:22Z"', u'manager', u'last_cleanup')
11 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 UPDATE simple_persistence SET json=? WHERE simple_persistence.feed IS NULL AND simple_persistence.plugin = ? AND simple_persistence."key" = ?
12 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 ('"2018-09-04T00:03:22Z"', u'db_vacuum', u'last_vacuum')
13 2018-09-05 03:00 INFO sqlalchemy.engine.base.Engine task1 COMMIT
14 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Connection <sqlite3.Connection object at 0x7fe454829ce0> being returned to pool
15 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Connection <sqlite3.Connection object at 0x7fe454829ce0> rollback-on-return
16 2018-09-05 03:00 DEBUG sqlalchemy.pool.NullPool task1 Closing connection <sqlite3.Connection object at 0x7fe454829ce0>
17 2018-09-05 03:00 DEBUG scheduler all tasks in schedule finished executing
18 2018-09-05 03:00 INFO apscheduler.executors.default Job "pt-* (trigger: interval[0:02:00], next run at: 2018-09-05 03:01:54 PDT)" executed successfully
19 2018-09-05 03:01 DEBUG apscheduler.scheduler Looking for jobs to run
20 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Created new connection <sqlite3.Connection object at 0x7fe4548293d0>
21 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Connection <sqlite3.Connection object at 0x7fe4548293d0> checked out from pool
22 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine SELECT apscheduler_jobs.id, apscheduler_jobs.job_state \nFROM apscheduler_jobs \nWHERE apscheduler_jobs.next_run_time <= ? ORDER BY apscheduler_jobs.next_run_time
23 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine (1536141715.712565,)
24 2018-09-05 03:01 DEBUG sqlalchemy.engine.base.Engine Col ('id', 'job_state')
25 2018-09-05 03:01 DEBUG sqlalchemy.engine.base.Engine Row (u'60924f166baf5ed4812629eefdf5cbe52196b4cb', <read-write buffer ptr 0x7fe4500044e0, size 571 at 0x7fe4500044a0>)
26 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Connection <sqlite3.Connection object at 0x7fe4548293d0> being returned to pool
27 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Connection <sqlite3.Connection object at 0x7fe4548293d0> rollback-on-return
28 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Closing connection <sqlite3.Connection object at 0x7fe4548293d0>
29 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Created new connection <sqlite3.Connection object at 0x7fe4548293d0>
30 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Connection <sqlite3.Connection object at 0x7fe4548293d0> checked out from pool
31 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine UPDATE apscheduler_jobs SET next_run_time=?, job_state=? WHERE apscheduler_jobs.id = ?
32 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine (1536141834.067449, <read-only buffer for 0x7fe4500077f0, size -1, offset 0 at 0x7fe42c5a81f0>, '60924f166baf5ed4812629eefdf5cbe52196b4cb')
33 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine COMMIT
34 2018-09-05 03:01 INFO apscheduler.executors.default Running job "pt-* (trigger: interval[0:02:00], next run at: 2018-09-05 03:03:54 PDT)" (scheduled at 2018-09-05 03:01:54.067449-07:00)
35 2018-09-05 03:01 DEBUG scheduler executing tasks: [u'pt-*']
36 2018-09-05 03:01 DEBUG scheduler task finished executing: task2
37 2018-09-05 03:01 DEBUG manager task2 Not running db cleanup, last run 2018-09-04 00:03:22
38 2018-09-05 03:01 DEBUG sqlalchemy.orm.path_registry task2 set 'memoized_setups' on path 'EntityRegistry((<Mapper at 0x7fe4586b1590; SimpleKeyValue>,))' to '{}'
39 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool task2 Created new connection <sqlite3.Connection object at 0x7fe44fffd118>
40 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> checked out from pool
41 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 BEGIN (implicit)
42 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 SELECT simple_persistence.feed AS simple_persistence_feed, simple_persistence.json AS simple_persistence_json, simple_persistence.id AS simple_persistence_id, simple_persistence.plugin AS simple_persistence_plugin, simple_persistence."key" AS simple_persistence_key, simple_persistence.added AS simple_persistence_added \nFROM simple_persistence \nWHERE simple_persistence.feed = ?
43 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 ('task2',)
44 2018-09-05 03:02 INFO sqlalchemy.engine.base.Engine task2 ROLLBACK
45 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> being returned to pool
46 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> rollback-on-return
47 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Closing connection <sqlite3.Connection object at 0x7fe44fffd118>
48 2018-09-05 03:02 CRITICAL task_queue Database error while running a task. Attempting to recover.
49 2018-09-05 03:02 DEBUG scheduler task finished executing: task1
50 Traceback (most recent call last):
51 File "/root/base/flexget/libs/Flexget/flexget/task_queue.py", line 48, in run
52 self.current_task.execute()
53 File "/root/base/flexget/libs/Flexget/flexget/task.py", line 72, in wrapper
54 return func(self, *args, **kw)
55 File "/root/base/flexget/libs/Flexget/flexget/task.py", line 643, in execute
56 fire_event('task.execute.started', self)
57 File "/root/base/flexget/libs/Flexget/flexget/event.py", line 106, in fire_event
58 result = event(*args, **kwargs)
59 File "/root/base/flexget/libs/Flexget/flexget/event.py", line 23, in __call__
60 return self.func(*args, **kwargs)
61 File "/root/base/flexget/libs/Flexget/flexget/utils/simple_persistence.py", line 195, in load_task
62 SimplePersistence.load(task.name)
63 File "/root/base/flexget/libs/Flexget/flexget/utils/simple_persistence.py", line 144, in load
64 for skv in session.query(SimpleKeyValue).filter(SimpleKeyValue.task == task).all():
65 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2737, in all
66 return list(self)
67 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2889, in __iter__
68 return self._execute_and_instances(context)
69 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2912, in _execute_and_instances
70 result = conn.execute(querycontext.statement, self._params)
71 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 948, in execute
72 return meth(self, multiparams, params)
73 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
74 return connection._execute_clauseelement(self, multiparams, params)
75 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
76 compiled_sql, distilled_params
77 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
78 context)
79 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
80 exc_info
81 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
82 reraise(type(exception), exception, tb=exc_tb, cause=cause)
83 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
84 context)
85 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 507, in do_execute
86 cursor.execute(statement, parameters)
87 OperationalError: (sqlite3.OperationalError) database is locked [SQL: u'SELECT simple_persistence.feed AS simple_persistence_feed, simple_persistence.json AS simple_persistence_json, simple_persistence.id AS simple_persistence_id, simple_persistence.plugin AS simple_persistence_plugin, simple_persistence."key" AS simple_persistence_key, simple_persistence.added AS simple_persistence_added \nFROM simple_persistence \nWHERE simple_persistence.feed = ?'] [parameters: ('task2',)] (Background on this error at: http://sqlalche.me/e/e3q8)
crash_report.2018.09.05.030209839767.log
Possible cause:
This issue is likely caused by that FlexGet and APScheduler use same sqlite3 database file db-config.sqlite and access it at the same time.
In the above crash report, from line 29 to 33, APScheduler created a connection <sqlite3.Connection object at 0x7fe4548293d0> to the sqlite3 database file to update next_run_time. It's a database write operation, so the sqlite3 database file was locked during the operation.
29 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Created new connection <sqlite3.Connection object at 0x7fe4548293d0>
30 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool Connection <sqlite3.Connection object at 0x7fe4548293d0> checked out from pool
31 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine UPDATE apscheduler_jobs SET next_run_time=?, job_state=? WHERE apscheduler_jobs.id = ?
32 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine (1536141834.067449, <read-only buffer for 0x7fe4500077f0, size -1, offset 0 at 0x7fe42c5a81f0>, '60924f166baf5ed4812629eefdf5cbe52196b4cb')
33 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine COMMIT
From line 39 to 87, It looks like that, before this write operation was fully completed and the connection <sqlite3.Connection object at 0x7fe4548293d0> was closed properly, FlexGet in another thread created a new database connection <sqlite3.Connection object at 0x7fe44fffd118> to query simple_persistence. Since the database file was still locked by the APScheduler's operation, the "database is locked" error occured.
39 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool task2 Created new connection <sqlite3.Connection object at 0x7fe44fffd118>
40 2018-09-05 03:01 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> checked out from pool
41 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 BEGIN (implicit)
42 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 SELECT simple_persistence.feed AS simple_persistence_feed, simple_persistence.json AS simple_persistence_json, simple_persistence.id AS simple_persistence_id, simple_persistence.plugin AS simple_persistence_plugin, simple_persistence."key" AS simple_persistence_key, simple_persistence.added AS simple_persistence_added \nFROM simple_persistence \nWHERE simple_persistence.feed = ?
43 2018-09-05 03:01 INFO sqlalchemy.engine.base.Engine task2 ('task2',)
44 2018-09-05 03:02 INFO sqlalchemy.engine.base.Engine task2 ROLLBACK
45 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> being returned to pool
46 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Connection <sqlite3.Connection object at 0x7fe44fffd118> rollback-on-return
47 2018-09-05 03:02 DEBUG sqlalchemy.pool.NullPool task2 Closing connection <sqlite3.Connection object at 0x7fe44fffd118>
48 2018-09-05 03:02 CRITICAL task_queue Database error while running a task. Attempting to recover.
49 2018-09-05 03:02 DEBUG scheduler task finished executing: task1
50 Traceback (most recent call last):
51 File "/root/base/flexget/libs/Flexget/flexget/task_queue.py", line 48, in run
52 self.current_task.execute()
53 File "/root/base/flexget/libs/Flexget/flexget/task.py", line 72, in wrapper
54 return func(self, *args, **kw)
55 File "/root/base/flexget/libs/Flexget/flexget/task.py", line 643, in execute
56 fire_event('task.execute.started', self)
57 File "/root/base/flexget/libs/Flexget/flexget/event.py", line 106, in fire_event
58 result = event(*args, **kwargs)
59 File "/root/base/flexget/libs/Flexget/flexget/event.py", line 23, in __call__
60 return self.func(*args, **kwargs)
61 File "/root/base/flexget/libs/Flexget/flexget/utils/simple_persistence.py", line 195, in load_task
62 SimplePersistence.load(task.name)
63 File "/root/base/flexget/libs/Flexget/flexget/utils/simple_persistence.py", line 144, in load
64 for skv in session.query(SimpleKeyValue).filter(SimpleKeyValue.task == task).all():
65 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2737, in all
66 return list(self)
67 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2889, in __iter__
68 return self._execute_and_instances(context)
69 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2912, in _execute_and_instances
70 result = conn.execute(querycontext.statement, self._params)
71 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 948, in execute
72 return meth(self, multiparams, params)
73 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
74 return connection._execute_clauseelement(self, multiparams, params)
75 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
76 compiled_sql, distilled_params
77 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
78 context)
79 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
80 exc_info
81 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
82 reraise(type(exception), exception, tb=exc_tb, cause=cause)
83 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
84 context)
85 File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 507, in do_execute
86 cursor.execute(statement, parameters)
87 OperationalError: (sqlite3.OperationalError) database is locked [SQL: u'SELECT simple_persistence.feed AS simple_persistence_feed, simple_persistence.json AS simple_persistence_json, simple_persistence.id AS simple_persistence_id, simple_persistence.plugin AS simple_persistence_plugin, simple_persistence."key" AS simple_persistence_key, simple_persistence.added AS simple_persistence_added \nFROM simple_persistence \nWHERE simple_persistence.feed = ?'] [parameters: ('task2',)] (Background on this error at: http://sqlalche.me/e/e3q8)
I have briefly looked into some related code of FlexGet and APScheduler. FlexGet shares same sqlalchemy.engine.Engine instance with APScheduler to access the database across threads, but it appears to not be thread-safe. FlexGet thread and APScheduler thread can create different connections to access the database concurrently.
Normally, these concurrent accesses should be quite rare, which causes this issue happens randomly. However, it has happened on my server quite constantly. It's probably because I run FlexGet at 2 minutes interval on a slow seedbox server with heavy I/O loads. Database operations can take a while to finish on that server, so this kind of collision is more likely to happen.
Temporary fix:
I have modified FlexGet to use a separate sqlite3 database file db-apscheduler.sqlite for APScheduler. Since then it has been running for almost three weeks without any issues.
diff --git a/flexget/plugins/daemon/scheduler.py b/flexget/plugins/daemon/scheduler.py
index 16fb35652..7892f6a2d 100644
--- a/flexget/plugins/daemon/scheduler.py
+++ b/flexget/plugins/daemon/scheduler.py
@@ -121,7 +121,18 @@ def setup_scheduler(manager):
global scheduler
if logging.getLogger().getEffectiveLevel() > logging.DEBUG:
logging.getLogger('apscheduler').setLevel(logging.WARNING)
- jobstores = {'default': SQLAlchemyJobStore(engine=manager.engine, metadata=Base.metadata)}
+ # jobstores = {'default': SQLAlchemyJobStore(engine=manager.engine, metadata=Base.metadata)}
+
+
+ # Temporary fix for "OperationalError: (sqlite3.OperationalError) database is locked" error:
+ # Use a separate sqlite3 database file 'db-apscheduler.sqlite' for APScheduler
+ import os
+ db_filename = os.path.join(manager.config_base, 'db-apscheduler.sqlite')
+ db_filename = db_filename.replace('\\', '\\\\')
+ database_uri = 'sqlite:///%s' % db_filename
+ jobstores = {'default': SQLAlchemyJobStore(url=database_uri)}
+
+
# If job was meant to run within last day while daemon was shutdown, run it once when continuing
job_defaults = {'coalesce': True, 'misfire_grace_time': 60 * 60 * 24}
try:temp_fix_database_is_locked.patch.txt
Additional information:
- FlexGet version: 2.14.20.dev
- Python version: 2.7.12
- Installation method: pip
- Using daemon (yes/no): yes
- OS and version: Ubuntu Server 16.04