Kolibri: Stuck on UPDATE CHANNEL task

Created on 3 Jun 2020  路  20Comments  路  Source: learningequality/kolibri

Observed behavior

When updating a large channel on a 0.13.2 Kolibri demo server, after clicking UPDATE CHANNEL I saw the progress bar jump form 0 to 100 very fast then go back to 0% progress and just gets stuck there. Kolibri esta stuckiendo!

Ina recently encountered a similar issue:
screen_shot_2020-06-03_at_11 58 05_am
see https://learningequality.slack.com/archives/CRM17EYQ5/p1591149618002100

Expected behavior

The UPDATE CHANNEL task to complete and progress to be displayed along the way.

User-facing consequences

Kolibri admins cannot update channels (for larger channels).

Errors and logs

INFO     Annotating ContentNode objects with children for level 1
ERROR    Job cd5f7ac88c03423f8d70b69a85b4f7e5 raised an exception: Traceback (most recent call last):
  File "/.../kolibri-0.13.2....whl/kolibri/core/tasks/worker.py", line 73, in handle_finished_future
    result = future.result()
  File "/.../kolibri-0.13.2....whl/kolibri/dist/py2only/concurrent/futures/_base.py", line 422, in result
    return self.__get_result()
  File "/.../kolibri-0.13.2....whl/kolibri/dist/py2only/concurrent/futures/thread.py", line 62, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/.../kolibri-0.13.2....whl/kolibri/core/tasks/worker.py", line 224, in wrap
    return f(*args, **kwargs)
  File "/.../kolibri-0.13.2....whl/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/.../kolibri-0.13.2....whl/kolibri/core/tasks/api.py", line 728, in _remoteimport
    check_for_cancel=check_for_cancel,
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/core/management/__init__.py", line 131, in call_command
    return command.execute(*args, **defaults)
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/.../kolibri-0.13.2....whl/kolibri/core/tasks/management/commands/base.py", line 110, in handle
    return self.handle_async(*args, **options)
  File "/.../kolibri-0.13.2....whl/kolibri/core/content/management/commands/importcontent.py", line 439, in handle_async
    renderable_only=options["renderable_only"],
  File "/.../kolibri-0.13.2....whl/kolibri/core/content/management/commands/importcontent.py", line 159, in download_content
    renderable_only=renderable_only,
  File "/.../kolibri-0.13.2....whl/kolibri/core/content/management/commands/importcontent.py", line 217, in _transfer
    .values("content_id")
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/db/models/query.py", line 364, in count
    return self.query.get_count(using=self.db)
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/db/models/sql/query.py", line 499, in get_count
    number = obj.get_aggregation(using, ['__count'])['__count']
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/db/models/sql/query.py", line 480, in get_aggregation
    result = compiler.execute_sql(SINGLE)
  File "/.../kolibri-0.13.2....whl/kolibri/dist/django/db/models/sql/compiler.py", line 899, in execute_sql
    raise original_exception
OperationalError: Expression tree is too large (maximum depth 1000)

Steps to reproduce

  1. IMPORT vN of a large channel in Kolibri
  2. PUBLISH an updated v(N+1) of the channel with lots of changes
  3. click VIEW CHANGES, and UPDATE CHANNEL in Kolibri to start the update process

Note: it is not clear what causes the error (is it large channels?), channels with many changes?, deep channels?

Suggestion: The KA-bg channel on the main Kolibri demo-server has not been updated from v6 to v7, so it can be used as a test case to reproduce. Maybe @lyw07 could monitor the logs live and who ever is debugging this can do the update process to monitor the js console in parallel.

Context

  • Kolibri version: 0.13.3
  • Operating system: Linux
  • DB: sqlite3 (for my demo server), postgres for UNW server
Device P1 - important performance
Source
picture ivanistheone

Most helpful comment

To fix this, we might have to change the API of get_nodes_to_transfer https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/management/commands/importcontent.py#L192
to return a chunked sequence of querysets instead.

For context, this is how we resolved this in the annotation case: https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/utils/annotation.py#L270 (basically, chunking the queries and doing batched operations) - in this case, it would be simpler, as it would just be a matter of taking the batched queries and summing the counts, and getting the list of files from them, so should be feasible to implement.

picture rtibbles on 3 Jun 2020
🎉2

All 20 comments

We experienced a similar issue in the post-update annotation preservation - the fundamental issue is that when we have too many node_ids and exclude_node_ids the SQL queries get too big, and trigger these sorts of errors.

I am not sure the UNW issue is identical, as that is running 0.12.x where the more nuanced upgrade pathway does not exist.

rtibbles picture rtibbles on 3 Jun 2020

I am not sure the UNW issue is identical, as that is running 0.12.x where the more nuanced upgrade pathway does not exist.

Agree. I just looked at the screenshot and it seems to have started and only stuck 20% through, so root cause must be different.

ivanistheone picture ivanistheone on 3 Jun 2020

To fix this, we might have to change the API of get_nodes_to_transfer https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/management/commands/importcontent.py#L192
to return a chunked sequence of querysets instead.

For context, this is how we resolved this in the annotation case: https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/utils/annotation.py#L270 (basically, chunking the queries and doing batched operations) - in this case, it would be simpler, as it would just be a matter of taking the batched queries and summing the counts, and getting the list of files from them, so should be feasible to implement.

rtibbles picture rtibbles on 3 Jun 2020
🎉2

Trying to update a medium-sized KA channel failed silently (task just disappeared in UI). After getting back to the channels list, the channel had dissapeared. Importing from scratch worked.

The logs contain this

ERROR 2020-06-05 16:44:27,463 worker Job 8793de2ab6ef498caf5c965ff98e9503 raised an exception: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 71, in handle_finished_future
    result = future.result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/_base.py", line 422, in result
    return self.__get_result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/thread.py", line 62, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 216, in wrap
    return f(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/analytics/utils.py", line 416, in _ping
    ping_once(started, server=server)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/analytics/utils.py", line 408, in ping_once
    create_and_update_notifications(data, nutrition_endpoints.PINGBACK)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/utils/decorators.py", line 185, in inner
    return func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/analytics/utils.py", line 339, in create_and_update_notifications
    ).update(active=False)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/utils.py", line 174, in __exit__
    self.release()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/utils.py", line 163, in release
    assert is_owned, "cannot release un-acquired lock"
AssertionError: cannot release un-acquired lock

via kolibri@kolibri-demo-worker-5f67c84987-7wdbt:~/kolibri_home/kolibri-demo/logs$ more kolibri.txt

ivanistheone picture ivanistheone on 5 Jun 2020

Ugh - 0.13.3? With redis backend or no?

rtibbles picture rtibbles on 5 Jun 2020

yes it's the main kolibri-demo server with 0.13.3 and redis backend

lyw07 picture lyw07 on 5 Jun 2020

@rtibbles Note we have 4x more KA-sized channels queued up for "UPDATE CHANNEL", so if you have any ideas for what to watch out for and what debug info to collect let us know (@lyw07 and I plan to go through the update process around 5pm PT today).

ivanistheone picture ivanistheone on 5 Jun 2020

Wondering if we should just make the lock a no-op in postgresql situations, as it's mostly to prevent issues occurring in SQLite.

Still a little concerning that the lock itself is going astray.

rtibbles picture rtibbles on 5 Jun 2020

New logs from trying to update KA-fr in Kolibri 0.13.3:

kolibri@kolibri-catalog-fr-app-7b5c7864dc-s5cj5:~/kolibri_home/kolibri-catalog-fr/logs$ tail -f kolibri.txt
INFO 2020-06-06 00:24:28,327 importchannel Downloading data for channel id 878ec2e6f88c5c268b1be6f202833cd4
INFO 2020-06-06 00:24:29,644 channel_import Older version 11 of channel 878ec2e6f88c5c268b1be6f202833cd4 already exists in database; removing old entries so we can upgrade to version 12
INFO 2020-06-06 00:24:29,938 channel_import Importing ContentTag data
INFO 2020-06-06 00:24:29,946 channel_import Importing ContentNode_has_prerequisite data
INFO 2020-06-06 00:24:29,948 channel_import Importing ContentNode_related data
INFO 2020-06-06 00:24:29,952 channel_import Importing ContentNode_tags data
INFO 2020-06-06 00:24:29,954 channel_import Importing ContentNode data
INFO 2020-06-06 00:24:40,264 channel_import Importing Language data
INFO 2020-06-06 00:24:40,275 channel_import Importing File data
INFO 2020-06-06 00:24:53,806 channel_import Importing LocalFile data
_ Running downgrade routines for kolibri.plugins.coach, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,192 __init__ kolibri.plugins.coach successfully updated
INFO 2020-06-06 00:24:53,197 __init__ Running downgrade routines for kolibri.plugins.user, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,198 __init__ kolibri.plugins.user successfully updated
INFO 2020-06-06 00:24:53,204 __init__ Running downgrade routines for kolibri.plugins.setup_wizard, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,204 __init__ kolibri.plugins.setup_wizard successfully updated
INFO 2020-06-06 00:24:53,213 __init__ Running downgrade routines for kolibri.plugins.facility, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,214 __init__ kolibri.plugins.facility successfully updated
INFO 2020-06-06 00:24:53,222 __init__ Running downgrade routines for kolibri.plugins.html5_viewer, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,222 __init__ kolibri.plugins.html5_viewer successfully updated
INFO 2020-06-06 00:24:53,229 __init__ Running downgrade routines for kolibri.plugins.device, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,229 __init__ kolibri.plugins.device successfully updated
INFO 2020-06-06 00:24:53,236 __init__ Running downgrade routines for kolibri.plugins.default_theme, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,236 __init__ kolibri.plugins.default_theme successfully updated
INFO 2020-06-06 00:24:53,242 __init__ Running downgrade routines for kolibri.plugins.media_player, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,242 __init__ kolibri.plugins.media_player successfully updated
INFO 2020-06-06 00:24:53,247 __init__ Running downgrade routines for kolibri.plugins.pdf_viewer, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,248 __init__ kolibri.plugins.pdf_viewer successfully updated
INFO 2020-06-06 00:24:53,254 __init__ Running downgrade routines for kolibri.plugins.slideshow_viewer, downgrading from 0.13.3 to 0.13.3
INFO 2020-06-06 00:24:53,254 __init__ kolibri.plugins.slideshow_viewer successfully updated
INFO 2020-06-06 00:24:53,260 cli Copying updated static files
INFO 2020-06-06 00:24:56,422 cli Invoking command collectstatic
environment variable KOLIBRI_DEBUG_SENTRY_BACKEND_DSN
INFO 2020-06-06 00:25:05,184 options Option SENTRY_ENVIRONMENT in section [Debug] being overridden by environment variable KOLIBRI_DEBUG_SENTRY_ENVIRONMENT
INFO 2020-06-06 00:25:05,511 options Option DATABASE_ENGINE in section [Database] being overridden by environment variable KOLIBRI_DATABASE_ENGINE
INFO 2020-06-06 00:25:05,513 options Option DATABASE_NAME in section [Database] being overridden by environment variable KOLIBRI_DATABASE_NAME
INFO 2020-06-06 00:25:05,513 options Option DATABASE_PORT in section [Database] being overridden by environment variable KOLIBRI_DATABASE_PORT
INFO 2020-06-06 00:25:05,515 options Option DATABASE_PASSWORD in section [Database] being overridden by environment variable KOLIBRI_DATABASE_PASSWORD
INFO 2020-06-06 00:25:05,515 options Option DATABASE_HOST in section [Database] being overridden by environment variable KOLIBRI_DATABASE_HOST
INFO 2020-06-06 00:25:05,516 options Option DATABASE_USER in section [Database] being overridden by environment variable KOLIBRI_DATABASE_USER
INFO 2020-06-06 00:25:05,517 options Option CACHE_BACKEND in section [Cache] being overridden by environment variable KOLIBRI_CACHE_BACKEND
INFO 2020-06-06 00:25:05,517 options Option CACHE_REDIS_MIN_DB in section [Cache] being overridden by environment variable KOLIBRI_CACHE_REDIS_MIN_DB
INFO 2020-06-06 00:25:05,518 options Option CACHE_LOCATION in section [Cache] being overridden by environment variable KOLIBRI_CACHE_LOCATION
INFO 2020-06-06 00:25:05,520 options Option CHERRYPY_START in section [Server] being overridden by environment variable KOLIBRI_CHERRYPY_START
INFO 2020-06-06 00:25:05,520 options Option RUN_MODE in section [Deployment] being overridden by environment variable KOLIBRI_RUN_MODE
INFO 2020-06-06 00:25:05,522 options Option SENTRY_FRONTEND_DSN in section [Debug] being overridden by environment variable KOLIBRI_DEBUG_SENTRY_FRONTEND_DSN
INFO 2020-06-06 00:25:05,522 options Option SENTRY_BACKEND_DSN in section [Debug] being overridden by environment variable KOLIBRI_DEBUG_SENTRY_BACKEND_DSN
INFO 2020-06-06 00:25:05,524 options Option SENTRY_ENVIRONMENT in section [Debug] being overridden by environment variable KOLIBRI_DEBUG_SENTRY_ENVIRONMENT
INFO 2020-06-06 00:25:06,644 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2020-06-06 00:25:07,384 cli Running Kolibri
INFO 2020-06-06 00:25:07,385 cli Starting Kolibri background workers
INFO 2020-06-06 00:25:07,391 server Starting Kolibri 0.13.3
INFO 2020-06-06 00:25:07,391 cherrypy.error ENGINE Listening for SIGHUP.
INFO 2020-06-06 00:25:07,392 cherrypy.error ENGINE Listening for SIGUSR1.
INFO 2020-06-06 00:25:07,392 cherrypy.error ENGINE Listening for SIGTERM.
INFO 2020-06-06 00:25:07,393 cherrypy.error ENGINE Listening for SIGINT.
INFO 2020-06-06 00:25:07,393 cherrypy.error ENGINE Bus STARTING
INFO 2020-06-06 00:25:07,908 utils Started new JOBCHECKER thread ID#b5ec4da642d34297ac77c7ee6928115a
INFO 2020-06-06 00:25:07,912 utils Started new JOBCHECKER thread ID#ac1cf790e6924247a4504adc9ba9a44f
INFO 2020-06-06 00:25:07,920 utils Started new SCHEDULECHECKER thread ID#8923ea6aa1cc4349943ef49b084006ca
INFO 2020-06-06 00:25:07,946 search Registering ourselves to zeroconf network with id '227f92b8cc9b18960f3691bf45a4b313'...
INFO 2020-06-06 00:25:08,234 search Kolibri instance '3da7bf1e2ef8a18f93b9fe194192ac84' joined zeroconf network; service info: {u'kolibri_version': u'0.13.3', u'operating_system': u'Linux', 'ip': '10.52.0.26', 'self': False, 'base_url': 'http://10.52.0.26:8080/', 'port': 8080, u'instance_id': u'3da7bf1e2ef8a18f93b9fe194192ac84', u'application': u'kolibri', 'host': u'3da7bf1e2ef8a18f93b9fe194192ac84.kolibri.local', u'device_name': u'kolibri-catalog-es-app-5ff7d9f5bc-qtmlt', 'local': False, 'id': u'3da7bf1e2ef8a18f93b9fe194192ac84'}
INFO 2020-06-06 00:25:08,788 cherrypy.error ENGINE Bus STARTED
INFO 2020-06-06 00:25:08,960 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2020-06-06 00:25:15,968 channel_import Importing AssessmentMetaData data
INFO 2020-06-06 00:25:21,036 channel_import Importing ChannelMetadata data
INFO 2020-06-06 00:25:23,898 channel_import Channel 878ec2e6f88c5c268b1be6f202833cd4 successfully imported into the database
INFO 2020-06-06 00:25:23,925 annotation Setting availability of non-topic ContentNode objects based on LocalFile availability in 58 batches of 489
INFO 2020-06-06 00:25:42,058 annotation Annotating ContentNode objects with children for 5 levels
INFO 2020-06-06 00:25:42,615 annotation Annotating ContentNode objects with children for level 5
INFO 2020-06-06 00:25:42,646 annotation Annotating ContentNode objects with children for level 4
INFO 2020-06-06 00:25:42,653 annotation Annotating ContentNode objects with children for level 3
INFO 2020-06-06 00:25:42,657 annotation Annotating ContentNode objects with children for level 2
INFO 2020-06-06 00:25:42,661 annotation Annotating ContentNode objects with children for level 1
ERROR 2020-06-06 00:25:42,832 storage Tried to update job with id 0ff221a8837641d98fc554177769fdf8 but it was not found
ERROR 2020-06-06 00:25:42,907 storage Tried to update job with id 0ff221a8837641d98fc554177769fdf8 but it was not found

the line

ERROR 2020-06-06 00:25:42,907 storage Tried to update job with id 0ff221a8837641d98fc554177769fdf8 but it was not found

now repeats indefinitely.

The effect of this in the UI was the task dissapreared and the KA fr channel also dissapreared from Kolibri.

I re-did the import (as if a new channel) and it started running OK. This error showed up in the logs, but the import task seems to be continuing fine:

RROR 2020-06-06 00:30:48,930 importcontent An error occurred during content import: [Errno 116] Stale file handle
INFO 2020-06-06 00:30:48,949 annotation Setting availability to True of 786 LocalFile objects based on passed in checksums
INFO 2020-06-06 00:30:49,299 annotation Setting availability of non-topic ContentNode objects based on LocalFile availability in 20 batches of 1432
INFO 2020-06-06 00:30:53,059 annotation Annotating ContentNode objects with children for 5 levels
INFO 2020-06-06 00:30:53,537 annotation Annotating ContentNode objects with children for level 5
INFO 2020-06-06 00:30:53,588 annotation Annotating ContentNode objects with children for level 4
INFO 2020-06-06 00:30:53,604 annotation Annotating ContentNode objects with children for level 3
INFO 2020-06-06 00:30:53,611 annotation Annotating ContentNode objects with children for level 2
INFO 2020-06-06 00:30:53,616 annotation Annotating ContentNode objects with children for level 1
ERROR 2020-06-06 00:30:53,809 storage Tried to update job with id 0ff221a8837641d98fc554177769fdf8 but it was not found
ERROR 2020-06-06 00:30:53,829 storage Tried to update job with id 0ff221a8837641d98fc554177769fdf8 but it was not found
ERROR 2020-06-06 00:30:53,984 worker Job 0ff221a8837641d98fc554177769fdf8 raised an exception: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 71, in handle_finished_future
    result = future.result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/_base.py", line 422, in result
    return self.__get_result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/thread.py", line 62, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 216, in wrap
    return f(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/api.py", line 728, in _remoteimport
    check_for_cancel=check_for_cancel,
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/__init__.py", line 131, in call_command
    return command.execute(*args, **defaults)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/management/commands/base.py", line 110, in handle
    return self.handle_async(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importcontent.py", line 439, in handle_async
    renderable_only=options["renderable_only"],
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importcontent.py", line 159, in download_content
    renderable_only=renderable_only,
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importcontent.py", line 353, in _transfer
    raise exception
IOError: [Errno 116] Stale file handle
ivanistheone picture ivanistheone on 6 Jun 2020

While debugging the above on last Friday, I saw this in the logs which I wonder why cherrpy is starting? Isn't this the uwsgi setup ? Maybe the worker still runs cherrpy?

INFO 2020-06-06 02:06:53,100 cherrypy.error ENGINE Caught signal SIGTERM.
INFO 2020-06-06 02:06:53,101 cherrypy.error ENGINE Bus STOPPING
INFO 2020-06-06 02:06:53,103 system Waiting for Kolibri to finish shutting down
INFO 2020-06-06 02:06:53,111 search Kolibri instance '559608e7570909772fdbeb2a42a51955' has left the zeroconf network.
WARNING 2020-06-06 02:06:53,194 utils JOBCHECKER shut down event received; closing.
WARNING 2020-06-06 02:06:53,195 utils JOBCHECKER shut down event received; closing.
WARNING 2020-06-06 02:06:53,500 utils SCHEDULECHECKER shut down event received; closing.
INFO 2020-06-06 02:06:58,418 cherrypy.error ENGINE Bus STOPPED
INFO 2020-06-06 02:06:58,419 cherrypy.error ENGINE Bus EXITING
INFO 2020-06-06 02:06:58,422 cherrypy.error ENGINE Bus EXITED
INFO 2020-06-06 02:06:58,423 cherrypy.error ENGINE Waiting for child threads to terminate...
INFO 2020-06-06 02:07:23,641 options Option DATABASE_ENGINE in section [Database] being overridden by environment variable KOLIBRI_DATABASE_ENGINE
INFO 2020-06-06 02:07:23,642 options Option DATABASE_NAME in section [Database] being overridden by environment variable KOLIBRI_DATABASE_NAME
INFO 2020-06-06 02:07:23,642 options Option DATABASE_PORT in section [Database] being overridden by environment variable KOLIBRI_DATABASE_PORT
INFO 2020-06-06 02:07:23,642 options Option DATABASE_PASSWORD in section [Database] being overridden by environment variable KOLIBRI_DATABASE_PASSWORD
INFO 2020-06-06 02:07:23,643 options Option DATABASE_HOST in section [Database] being overridden by environment variable KOLIBRI_DATABASE_HOST
ivanistheone picture ivanistheone on 8 Jun 2020

The un-ackquired lock error showed up again while importing the pt-BR into the main demo server (see below).

INFO 2020-06-06 01:11:56,608 channel_import Importing AssessmentMetaData data
INFO 2020-06-06 01:12:00,094 channel_import Importing ChannelMetadata data
INFO 2020-06-06 01:12:00,127 channel_import Channel 2ac071c4672354f2aa78953448f81e50 successfully imported into the database
INFO 2020-06-06 01:12:02,491 annotation Setting availability of non-topic ContentNode objects based on LocalFile availability in 43 batches of 634
INFO 2020-06-06 01:12:37,711 annotation Annotating ContentNode objects with children for 5 levels
INFO 2020-06-06 01:12:40,174 annotation Annotating ContentNode objects with children for level 5
INFO 2020-06-06 01:12:40,425 annotation Annotating ContentNode objects with children for level 4
INFO 2020-06-06 01:12:40,486 annotation Annotating ContentNode objects with children for level 3
INFO 2020-06-06 01:12:40,495 annotation Annotating ContentNode objects with children for level 2
INFO 2020-06-06 01:12:40,503 annotation Annotating ContentNode objects with children for level 1
ERROR 2020-06-06 01:12:41,804 importchannel An error occurred during channel import: cannot release un-acquired lock
ERROR 2020-06-06 01:12:41,994 worker Job 70ba4954d9204cae9a6ab0bd416dc453 raised an exception: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 71, in handle_finished_future
    result = future.result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/_base.py", line 422, in result
    return self.__get_result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/thread.py", line 62, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 216, in wrap
    return f(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/api.py", line 698, in _remoteimport
    check_for_cancel=check_for_cancel,
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/__init__.py", line 131, in call_command
    return command.execute(*args, **defaults)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/management/commands/base.py", line 110, in handle
    return self.handle_async(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 213, in handle_async
    options["channel_id"], options["baseurl"], options["no_upgrade"]
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 97, in download_channel
    self._transfer(DOWNLOAD_METHOD, channel_id, baseurl, no_upgrade=no_upgrade)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 134, in _transfer
    filetransfer, channel_id, dest, no_upgrade=no_upgrade
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 199, in _start_file_transfer
    retry_import(e, skip_404=False)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/utils/import_export_content.py", line 159, in retry_import
    raise e
AssertionError: cannot release un-acquired lock

and the same error again on the kolibri-catalog-hi server

INFO 2020-06-06 01:11:56,608 channel_import Importing AssessmentMetaData data
INFO 2020-06-06 01:12:00,094 channel_import Importing ChannelMetadata data
INFO 2020-06-06 01:12:00,127 channel_import Channel 2ac071c4672354f2aa78953448f81e50 successfully imported into the database
INFO 2020-06-06 01:12:02,491 annotation Setting availability of non-topic ContentNode objects based on LocalFile availability in 43 batches of 634
INFO 2020-06-06 01:12:37,711 annotation Annotating ContentNode objects with children for 5 levels
INFO 2020-06-06 01:12:40,174 annotation Annotating ContentNode objects with children for level 5
INFO 2020-06-06 01:12:40,425 annotation Annotating ContentNode objects with children for level 4
INFO 2020-06-06 01:12:40,486 annotation Annotating ContentNode objects with children for level 3
INFO 2020-06-06 01:12:40,495 annotation Annotating ContentNode objects with children for level 2
INFO 2020-06-06 01:12:40,503 annotation Annotating ContentNode objects with children for level 1
ERROR 2020-06-06 01:12:41,804 importchannel An error occurred during channel import: cannot release un-acquired lock
ERROR 2020-06-06 01:12:41,994 worker Job 70ba4954d9204cae9a6ab0bd416dc453 raised an exception: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 71, in handle_finished_future
    result = future.result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/_base.py", line 422, in result
    return self.__get_result()
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/py2only/concurrent/futures/thread.py", line 62, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/worker.py", line 216, in wrap
    return f(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/api.py", line 698, in _remoteimport
    check_for_cancel=check_for_cancel,
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/__init__.py", line 131, in call_command
    return command.execute(*args, **defaults)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/dist/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/tasks/management/commands/base.py", line 110, in handle
    return self.handle_async(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 213, in handle_async
    options["channel_id"], options["baseurl"], options["no_upgrade"]
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 97, in download_channel
    self._transfer(DOWNLOAD_METHOD, channel_id, baseurl, no_upgrade=no_upgrade)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 134, in _transfer
    filetransfer, channel_id, dest, no_upgrade=no_upgrade
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/management/commands/importchannel.py", line 199, in _start_file_transfer
    retry_import(e, skip_404=False)
  File "/usr/local/lib/python2.7/dist-packages/kolibri/core/content/utils/import_export_content.py", line 159, in retry_import
    raise e
AssertionError: cannot release un-acquired lock

ERROR 2020-06-06 01:12:42,017 storage Tried to update job with id
ivanistheone picture ivanistheone on 8 Jun 2020

While debugging the above on last Friday, I saw this in the logs which I wonder why cherrpy is starting? Isn't this the uwsgi setup ? Maybe the worker still runs cherrpy?

Oh.. I configured the environment variable KOLIBRI_CHERRYPY_START to be False in both app and worker, but it looks like we are still starting cherrypy even with this env var set to be False due to some code changes in Kolibri, as it's working fine for cloud kolibri servers which are running 0.12.9. I will file a different issue on this. Thank you for pointing this out! @ivanistheone

Issue filed here: https://github.com/learningequality/kolibri/issues/7009

lyw07 picture lyw07 on 9 Jun 2020

I have closed #7009 as this is intentional behaviour. We use cherrypy to manage our non-http services, and the KOLIBRI_CHERRYPY_START flag does not actually flag whether Cherrypy starts or not, just whether Cherrypy serves http.

rtibbles picture rtibbles on 9 Jun 2020
👍1

ah sorry! thank you for the explanation!

lyw07 picture lyw07 on 9 Jun 2020

Putting this in the 0.14 milestone to keep it visible, but we may want to apply any fixes on the 0.13 release branch?

indirectlylit picture indirectlylit on 11 Jun 2020

Kolibri admins cannot update channels (for larger channels).

Is this true across the board? If so, this should be a P0?

indirectlylit picture indirectlylit on 14 Jul 2020

Note by @jonboiser that we would probably want a large channel (content count, tree size) but with small content size.

Also, noting that, above, @rtibbles has described the solution:

To fix this, we might have to change the API of get_nodes_to_transfer https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/management/commands/importcontent.py#L192
to return a chunked sequence of querysets instead.

For context, this is how we resolved this in the annotation case: https://github.com/learningequality/kolibri/blob/develop/kolibri/core/content/utils/annotation.py#L270 (basically, chunking the queries and doing batched operations) - in this case, it would be simpler, as it would just be a matter of taking the batched queries and summing the counts, and getting the list of files from them, so should be feasible to implement.

nucleogenesis picture nucleogenesis on 30 Jul 2020

I realized after the discussion above, that this was also solved by #7274 - where it explicitly uses batching to prevent these kind of errors from occurring. However, there is still an extant issue for regular content import that could still be triggered.

rtibbles picture rtibbles on 31 Jul 2020

Seeing this when trying to start KDP (which is on 0.13):

ERROR    Job 4758db3b6f8d4bf79883282ca8c50122 raised an exception: Traceback (most recent call last):
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/tasks/worker.py", line 71, in handle_finished_future
    result = future.result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/tasks/worker.py", line 216, in wrap
    return f(*args, **kwargs)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/tasks/job.py", line 178, in y
    result = func(*args, **kwargs)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/analytics/utils.py", line 416, in _ping
    ping_once(started, server=server)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/analytics/utils.py", line 408, in ping_once
    create_and_update_notifications(data, nutrition_endpoints.PINGBACK)
  File "/usr/lib/python3.7/contextlib.py", line 74, in inner
    return func(*args, **kwds)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/analytics/utils.py", line 339, in create_and_update_notifications
    ).update(active=False)
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/tasks/utils.py", line 174, in __exit__
    self.release()
  File "/home/jamalex/.virtualenvs/kolibri-data-portal/lib/python3.7/site-packages/kolibri/core/tasks/utils.py", line 163, in release
    assert is_owned, "cannot release un-acquired lock"
AssertionError: cannot release un-acquired lock
jamalex picture jamalex on 12 Sep 2020

The specific issue here was fixed in #7274 - so I am closing this. There are other extant issues logged elsewhere that capture some of the above.

rtibbles picture rtibbles on 23 Mar 2021
Was this page helpful?
0 / 5 - 0 ratings

Related issues

jonboiser picture jonboiser  路  5Comments
radinamatic picture radinamatic  路  4Comments
radinamatic picture radinamatic  路  3Comments
indirectlylit picture indirectlylit  路  5Comments
kollivier picture kollivier  路  4Comments