Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Logger API error leads to "database is locked" error for pex running on Mac #6810

Closed
ivanistheone opened this issue Apr 27, 2020 · 2 comments
Closed

Logger API error leads to "database is locked" error for pex running on Mac #6810

ivanistheone opened this issue Apr 27, 2020 · 2 comments
Assignees
@jredrejo
Labels
bug Behavior is wrong or broken DEV: backend Python, databases, networking, filesystem... P1 - important Priority: High impact on UX
Milestone
0.14.0

Comments

@ivanistheone
Copy link
Contributor

ivanistheone commented Apr 27, 2020 •
edited
Loading

Observed behavior

Sorry somethieng went wrong when trying to access an H5P node
http://127.0.0.1:8080/en/learn/#/topics/c/84703961e747568696509b98e8bdd68b

Screen Shot 2020-04-27 at 2 45 24 PM

Same content node worked later on.

Expected behavior

Render the H5P content.

User-facing consequences

Difficulty using H5P content.

Errors and logs

JS console has this non-critical missing translation string error:

filePresetStrings.js:46 [ERROR: kolibri/core/assets/src/views/ContentRenderer/filePresetStrings.js] Download translation string not defined for 'h5p'

then the actual errors are

PATCH http://127.0.0.1:8080/api/logger/contentsummarylog/24ba10107cc64539702b13c82f0b4af2/ 500 (Internal Server Error)

and

[ERROR: kolibri/core/assets/src/api-resource.js] An error occurred 
{request: {…}, url: "/api/logger/contentsummarylog/24ba10107cc64539702b13c82f0b4af2/", raw: XMLHttpRequest, status: {…}, headers: {…}, …}entity: "<h1>Server Error (500)</h1>"headers: {Content-Length: "27", Content-Type: "text/html", Date: "Mon, 27 Apr 2020 18:43:04 GMT", Server: "0.0.0.0", Vary: "Cookie", …}raw: XMLHttpRequest {readyState: 4, timeout: 0, withCredentials: false, upload: XMLHttpRequestUpload, onreadystatechange: ƒ, …}request: {path: "/api/logger/contentsummarylog/24ba10107cc64539702b13c82f0b4af2/", method: "PATCH", entity: "{"end_timestamp":"2020-04-27T18:43:03.536Z","time_spent":23.606}", params: {…}, originator: ƒ, …}status: {code: 500, text: "Internal Server Error"}url: "/api/logger/contentsummarylog/24ba10107cc64539702b13c82f0b4af2/"__proto__: Object
(anonymous) @ kolibri.core.default_frontend-0.13.2.js:1

[... 100 lines omitted ]

(anonymous) @ VM381 hashiframe-225f83f52c0ccc2c353c.js:1

Server logs are clean -- only 200, so not sure where this 500 came from...

INFO     127.0.0.1 - - "GET /content/storage/a/d/ad95b19a750f006976573e3199b0ca4d.png HTTP/1.1" 200 10948 "http://127.0.0.1:8080/en/learn/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     Initializing background log saving process
INFO     127.0.0.1 - - "GET /static/kolibri.plugins.h5p_viewer.main/kolibri.plugins.h5p_viewer.main0.13.2.css HTTP/1.1" 200 210 "http://127.0.0.1:8080/en/learn/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/kolibri.plugins.h5p_viewer.main/kolibri.plugins.h5p_viewer.main-0.13.2.js HTTP/1.1" 200 5730 "http://127.0.0.1:8080/en/learn/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/content/hashiframe-225f83f52c0ccc2c353c.js HTTP/1.1" 200 22928 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/kolibri.plugins.h5p_viewer.main/kolibri.plugins.h5p_viewer.main-0.13.2.js.map HTTP/1.1" 200 16723 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/kolibri.plugins.learn.app/kolibri.plugins.learn.app-0.13.2.js.map HTTP/1.1" 200 246437 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/kolibri.core.default_frontend/kolibri.core.default_frontend-0.13.2.js.map HTTP/1.1" 200 1090787 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"
INFO     127.0.0.1 - - "GET /static/assets/logo.ico HTTP/1.1" 200 5430 "http://127.0.0.1:8080/en/learn/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"

Context

Tell us about your environment, including:

  • Kolibri version: 0.13.2 via pex (using Python 3.6.9)
  • Operating system: Mac
  • Browser: Chrome

Steps to reproduce

wget https://github.com/learningequality/kolibri/releases/download/v0.13.2/kolibri-0.13.2.pex

mkdir -p ~/.kolibrihomes/kolibri-0.13.2
export KOLIBRI_HOME=~/.kolibrihomes/kolibri-0.13.2

python kolibri-0.13.2.pex manage provisiondevice \
                          --facility "$USER's Kolibri Facility" \
                          --preset informal \
                          --superusername devowner \
                          --superuserpassword admin123 \
                          --language_id en \
                          --verbosity 0 \
                          --noinput

python kolibri-0.13.2.pex plugin enable kolibri.plugins.h5p_viewer

python kolibri-0.13.2.pex manage importchannel network a791922463b2587f9a8f3987efe8b7c9
python kolibri-0.13.2.pex manage importcontent network a791922463b2587f9a8f3987efe8b7c9

python kolibri-0.13.2.pex start --foreground

navigate to http://127.0.0.1:8080/en/learn/#/topics/c/84703961e747568696509b98e8bdd68b

Update

After restarting Kolibri (this time running using python kolibri-0.13.2.pex start --debug --foreground) an viewing the same node, upon navigating to the parent directory another contensession log error occured, this time with traceback -- DB locked error:

{request: {…}, url: "/api/logger/contentsessionlog/b7e8ba7b89fb250287f1795b878745f0/", raw: XMLHttpRequest, status: {…}, headers: {…}, …}entity: "OperationalError at /api/logger/contentsessionlog/"headers: {Content-Length: "27980", Content-Type: "text/plain", Date: "Mon, 27 Apr 2020 19:03:30 GMT", Server: "0.0.0.0", Vary: "Cookie", …}raw: XMLHttpRequest {readyState: 4, timeout: 0, withCredentials: false, upload: XMLHttpRequestUpload, onreadystatechange: ƒ, …}request: {path: "/api/logger/contentsessionlog/b7e8ba7b89fb250287f1795b878745f0/", method: "PATCH", entity: "{"start_timestamp":"2020-04-27T19:03:20.547Z","end…p":"2020-04-27T19:03:29.388Z","time_spent":8.656}", params: {…}, originator: ƒ, …}status: {code: 500, text: "Internal Server Error"}url: "/api/logger/contentsessionlog/b7e8ba7b89fb250287f1795b878745f0/"__proto__: Object

ERROR    Internal Server Error: /api/logger/contentsessionlog/b7e8ba7b89fb250287f1795b878745f0/
Traceback (most recent call last):
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/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 "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/core/handlers/base.py", line 187, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/core/handlers/base.py", line 185, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/views/decorators/csrf.py", line 58, in wrapped_view
    return view_func(*args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/viewsets.py", line 116, in view
    return self.dispatch(request, *args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/views.py", line 495, in dispatch
    response = self.handle_exception(exc)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/views.py", line 455, in handle_exception
    self.raise_uncaught_exception(exc)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/views.py", line 492, in dispatch
    response = handler(request, *args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/mixins.py", line 84, in partial_update
    return self.update(request, *args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/core/logger/api.py", line 85, in update
    self.perform_update(serializer)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/mixins.py", line 80, in perform_update
    serializer.save()
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/serializers.py", line 209, in save
    self.instance = self.update(self.instance, validated_data)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/rest_framework/serializers.py", line 986, in update
    instance.save()
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/core/logger/models.py", line 128, in save
    super(ContentSessionLog, self).save(*args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/core/auth/models.py", line 222, in save
    super(AbstractFacilityDataModel, self).save(*args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/morango/models/core.py", line 547, in save
    super(SyncableModel, self).save(*args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/morango/models/fields/uuids.py", line 123, in save
    super(UUIDModelMixin, self).save(*args, **kwargs)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/base.py", line 808, in save
    force_update=force_update, update_fields=update_fields)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/base.py", line 838, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/base.py", line 905, in _save_table
    forced_update)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/base.py", line 955, in _do_update
    return filtered._update(values) > 0
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/query.py", line 667, in _update
    return query.get_compiler(self.db).execute_sql(CURSOR)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/sql/compiler.py", line 1204, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/sql/compiler.py", line 899, in execute_sql
    raise original_exception
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/models/sql/compiler.py", line 889, in execute_sql
    cursor.execute(sql, params)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/backends/utils.py", line 79, in execute
    return super(CursorDebugWrapper, self).execute(sql, params)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/Users/ivan/.pex/install/kolibri-0.13.2-py2.py3-none-any.whl.de564528c30c5f65fdf71fe55dd746322395b781/kolibri-0.13.2-py2.py3-none-any.whl/kolibri/dist/django/db/backends/sqlite3/base.py", line 328, in execute
    return Database.Cursor.execute(self, query, params)
django.db.utils.OperationalError: database is locked
@ivanistheone
Copy link
Contributor Author

I had a suspicion this was not H5P related so I tested again with another channel:

python kolibri-0.13.2.pex manage importchannel network c401c87e3cf652128fd3efaa5b3774f2
python kolibri-0.13.2.pex manage importcontent network c401c87e3cf652128fd3efaa5b3774f2

and I got the same DB locked error when the contentsessionlog API call happens

@ivanistheone ivanistheone changed the title Logger API errors when viewing H5P content nodes Logger API error leads to "database is locked" error for pex running on Mac Apr 27, 2020
@indirectlylit indirectlylit added DEV: backend Python, databases, networking, filesystem... P1 - important Priority: High impact on UX bug Behavior is wrong or broken labels Apr 28, 2020
@indirectlylit indirectlylit added this to the upcoming patch milestone Apr 28, 2020
@jredrejo jredrejo self-assigned this Apr 28, 2020
@jredrejo
Copy link
Member

jredrejo commented Jul 3, 2020

@ivanistheone thank you for your report. I am closing this issue because it's a duplicated of #7125 where Morango work is being done by others

@jredrejo jredrejo closed this as completed Jul 3, 2020
@indirectlylit indirectlylit modified the milestones: upcoming patch, 0.14.0 Jul 9, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jredrejo jredrejo

Labels
bug Behavior is wrong or broken DEV: backend Python, databases, networking, filesystem... P1 - important Priority: High impact on UX
Projects
None yet
Milestone
0.14.0
Development

No branches or pull requests
3 participants
@ivanistheone @jredrejo @indirectlylit