Unable to cleanly start kolibri: 'database is locked' error

intelliant01 commented 5 years ago

Observed behavior

Kolibri doesn't start completely. Database lock errors are visible in daemon.txt (shared below).

This is true of .deb package. It works fine with .pex.

Expected behavior

Kolibri should start and login screen should be accessible.

User-facing consequences

Unable to use Kolibri on Ubuntu with the deb package on Ubuntu.

Errors and logs

daemon.txt -

INFO     Attempting a ping.
INFO     Started new JOBCHECKER thread ID#9f33bbb23b0d4c5b93f3c8df577ddbf5
INFO     Updating num_coach_content on existing channels
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlite3.OperationalError: database is locked

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/bin/kolibri", line 9, in <module>
    load_entry_point('kolibri==0.12.7', 'console_scripts', 'kolibri')()
  File "/usr/lib/python3/dist-packages/kolibri/utils/cli.py", line 625, in main
    start(port, daemon=daemon)
  File "/usr/lib/python3/dist-packages/kolibri/utils/cli.py", line 319, in start
    server.start(port=port, run_cherrypy=run_cherrypy)
  File "/usr/lib/python3/dist-packages/kolibri/utils/server.py", line 113, in start
    update_channel_metadata()
  File "/usr/lib/python3/dist-packages/kolibri/core/content/utils/annotation.py", line 73, in update_channel_metadata
    update_num_coach_contents()
  File "/usr/lib/python3/dist-packages/kolibri/core/content/utils/annotation.py", line 167, in update_num_coach_contents
    .values(num_coach_contents=cast(ContentNodeTable.c.coach_content, Integer()))
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 948, in execute
    return meth(self, multiparams, params)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1200, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
    exc_info
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/util/compat.py", line 265, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/util/compat.py", line 248, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) database is locked [SQL: 'UPDATE content_contentnode SET num_coach_contents=CAST(content_contentnode.coach_content AS INTEGER) WHERE content_contentnode.kind != ?'] [parameters: ('topic',)] (Background on this error at: http://sqlalche.me/e/e3q8)
INFO     Sqlite database Vacuum finished.
INFO     Next Vacuum at 3AM local server time (in 333.71666666666664 minutes).
INFO     Ping succeeded! (response: {'id': 294901, 'messages': []})
INFO     Sleeping for 1440.0 minutes.

kolibri.txt -

INFO 2019-07-30 21:18:24,278 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-07-30 21:22:19,167 vacuumsqlite Sqlite database Vacuum finished.
INFO 2019-07-30 21:22:19,290 cli Running 'kolibri start' as daemon (system service)
INFO 2019-07-30 21:22:19,476 cli Kolibri running on:
INFO 2019-07-30 21:22:19,477 cli Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt
INFO 2019-07-30 21:22:20,369 ping Attempting a ping.
INFO 2019-07-30 21:22:21,940 utils Started new JOBCHECKER thread ID#9f33bbb23b0d4c5b93f3c8df577ddbf5
INFO 2019-07-30 21:22:23,275 annotation Updating num_coach_content on existing channels
INFO 2019-07-30 21:26:16,773 vacuumsqlite Sqlite database Vacuum finished.
INFO 2019-07-30 21:26:16,828 vacuumsqlite Next Vacuum at 3AM local server time (in 333.71666666666664 minutes).
INFO 2019-07-30 21:26:26,998 ping Ping succeeded! (response: {'id': 294901, 'messages': []})
INFO 2019-07-30 21:26:39,702 ping Sleeping for 1440.0 minutes.

Steps to reproduce

Install kolibri 0.2.7 deb package on Ubuntu 18.04 and try to start it.

Context

kolibri 0.2.7 deb Ubuntu 18.04

Experienced the same error when trying with kolibri server as well.

indirectlylit commented 5 years ago

Transferring to the Debian repo

benjaoming commented 5 years ago

Hi @intelliant01 - the version mentioned as 0.2.7, I assume is kolibri-server?

CC: @jredrejo

intelliant01 commented 5 years ago

Hi @benjaoming . Sorry I meant Kolibri 0.12.7. The problem manifests even with Kolibri Deb standalone as well as with kolibri-server. Both scenarios tested.

benjaoming commented 5 years ago

Thanks for adding that detail @intelliant01 :)

jredrejo commented 5 years ago

@intelliant01 please, take a look to the steps I have left in https://github.com/learningequality/kolibri-server/issues/20 to try to troubleshoot the problem. I think they're not related to kolibri-server nor to kolibri-installer-debian but we should find the solution anyway.

benjaoming commented 4 years ago

@intelliant01 have you seen this problem in 0.13?

learningequality / kolibri-installer-debian