Kolibri: errors during startup (database locked, DatabaseIDModel does not exist)

[indirectlylit]

Observed behavior

Attempting to run kolibri start on the most recent develop branch I get the errors below. This does not happen with the devserver.

At this point, I cannot load Kolibri.

Expected behavior

No errors, Kolibri loads

User-facing consequences

sadness, regret

Errors and logs

INFO     Running 'kolibri start' in foreground...
INFO:kolibri.utils.cli:Running 'kolibri start' in foreground...
INFO     Kolibri running on:

INFO:kolibri.utils.cli:Kolibri running on:

    http://127.0.0.1:8080/
    http://192.168.1.2:8080/

INFO     Attempting a ping.
INFO:kolibri.core.analytics.management.commands.ping:Attempting a ping.
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/morango/models.py", line 71, in get_or_create_current_database_id
    return cls.objects.get(current=True)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/query.py", line 380, in get
    self.model._meta.object_name
morango.models.DoesNotExist: DatabaseIDModel matching query does not exist.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/backends/sqlite3/base.py", line 328, in execute
    return Database.Cursor.execute(self, query, params)
sqlite3.OperationalError: database is locked

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

Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.6.5/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/Users/d/Projects/learning_equality/repos/k011x/kolibri/utils/server.py", line 106, in run
    call_command("ping")
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/core/management/__init__.py", line 131, in call_command
    return command.execute(*args, **defaults)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/Users/d/Projects/learning_equality/repos/k011x/kolibri/core/analytics/management/commands/ping.py", line 46, in handle
    data = self.perform_ping(server)
  File "/Users/d/Projects/learning_equality/repos/k011x/kolibri/core/analytics/management/commands/ping.py", line 60, in perform_ping
    instance, _ = InstanceIDModel.get_or_create_current_instance()
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/morango/models.py", line 110, in get_or_create_current_instance
    "database": DatabaseIDModel.get_or_create_current_database_id(),
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/morango/models.py", line 73, in get_or_create_current_database_id
    return cls.objects.create()
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/morango/models.py", line 38, in create
    DatabaseIDModel.objects.update(current=False)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/query.py", line 647, in update
    rows = query.get_compiler(self.db).execute_sql(CURSOR)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 1204, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 899, in execute_sql
    raise original_exception
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 889, in execute_sql
    cursor.execute(sql, params)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/d/Projects/learning_equality/repos/k011x/.venv/lib/python3.6/site-packages/django/db/backends/sqlite3/base.py", line 328, in execute
    return Database.Cursor.execute(self, query, params)
django.db.utils.OperationalError: database is locked

INFO     Started new MESSAGEPROCESSOR thread ID#ack-one-echo-lake
INFO:iceqube.common.utils.MESSAGEPROCESSOR[ack-one-echo-lake]:Started new MESSAGEPROCESSOR thread ID#ack-one-echo-lake
INFO     Started new SCHEDULER thread ID#mobile-skylark-bluebird-uniform
INFO:iceqube.common.utils.SCHEDULER[mobile-skylark-bluebird-uniform]:Started new SCHEDULER thread ID#mobile-skylark-bluebird-uniform
INFO     Started new WORKERMESSAGEHANDLER thread ID#beer-red-five-eleven
INFO:iceqube.common.utils.WORKERMESSAGEHANDLER[beer-red-five-eleven]:Started new WORKERMESSAGEHANDLER thread ID#beer-red-five-eleven
INFO     Sqlite database Vacuum finished.
INFO:kolibri.core.deviceadmin.management.commands.vacuumsqlite:Sqlite database Vacuum finished.
INFO     Next Vacuum in 10 minutes.
INFO:kolibri.core.deviceadmin.management.commands.vacuumsqlite:Next Vacuum in 10 minutes.
INFO:cherrypy.error:[26/Sep/2018:15:15:49] ENGINE Bus STARTING
INFO:cherrypy.error:[26/Sep/2018:15:15:49] ENGINE Serving on http://0.0.0.0:8080
INFO:cherrypy.error:[26/Sep/2018:15:15:49] ENGINE Bus STARTED

Steps to reproduce

make assets
kolibri start

Context

0.11

[jredrejo]

I think we should review the frequency of the vacuum interval. We set it very aggresive for testing purposes and never reduced it to a reasonable interval.
Relates #4067

[ralphiee22]

Thanks for the insight @jredrejo. Upon removing the vacuum call the above error stops appearing. I wonder if we can make it blocking for at least the first call, then threaded thereafter

[jredrejo]

It would be good to be able to do vacuum before anything else is done in Kolibri when booting because it warranties the db is in the best state before beginning to use. However, it's not something needed every day. It's important to do it after importing or deleting a channel (doing it so was not possible because the database can't have open queries to do vacuum)
I like your idea of making it blocking at first. In any normal computer it takes no longer than 4 or 5 seconds (usually 1 second if the database is in a good shape). My concern would be in places as Raspberry pi, where it's run on a SD card. I don't know if the time needed would be too long there.

If we can't set it at booting, keeping it in a thread executed every few minutes gives the server the oportunity to try vacuum often, and it will be done when no db queries are being executed.

[indirectlylit]

does this mean that vacuuming might cause a DB locked error if simultaneous access occurs?

Originally we had suspected it would not cause an error, but only cancel the vacuum

[jredrejo]

Logic seems to point so, but I have never been able to see it or force it. We have been using the aggressive vacuum in develop since mid July and I have never had or heard of any problem.

If that's the case the safest approach would be doing vacuum only on startup, in a blocking process.

The downside on doing vacuum only on startup is that it's useless in servers that are kept alive using apache or nginx and are not restarted frequently. A couple of seconds being locked every hour or so should not be a problem (if it were a real problem)

As usual, that's another trade-off where we have to choose what's the less bad solution.

[indirectlylit]

Sounds right. Let's

1. initially vacuum on start-up in a blocking step
2. reduce frequency of vacuum in #4067 to once per day at 3AM local time according to the server, which should minimize impact

[benjaoming]

once per day at 3AM local time according to the server, which should minimize impact

There are a lot of environments with either 1) power blackouts or 2) intentional power-off on devices. If these cases are covered by vacuuming during start-up, that's fine.. and then devices that are "always-on" are doing vacuuming during night, that's all fine!

[indirectlylit]

I believe this is addressed