Delay with the coach interface on Kolibri

Bruce · February 12, 2020, 8:53am

Hello,
We have installed Kolibri on Rachel 2.0 and have been using it for quite sometimes. I have read that the version of 0.13 will solve the lag on the coach interface but it is not the case on our site.
Whenever we click on the coach (be for checking the report, creating quizzes, etc…) it takes more than 10 mins to respond and sometimes it just doesn’t respond. Is there anything I can do to stop that? It is really affecting classes

Kolibri info:

Version: 0.13.0
OS: Linux-3.10.61-ltsi-06292015-x86_64-with-Ubuntu-14.04-trusty
Installer: apt
Server: Kolibri internal server
Database: /root/.kolibri/db.sqlite3
Device name: WAPD-235N-Server
Free disk space: 1 GB
Server time: Wed Feb 05 2020 13:14:25 GMT+0200 (Central Africa Time)
Server timezone: America/Los_Angeles

[Kolibri log file ]

benjamin · February 14, 2020, 4:37pm

Dear @Bruce - great that you posted the log file. I see the following timeout of interest:

ERROR 2020-02-05 01:35:29,493 exception Internal Server Error: /api/logger/examattemptlog/e0d71a8104b3ee5a66d5d6d4d867a891/
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/http/request.py", line 332, in read
    return self._stream.read(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/wsgi.py", line 47, in read
    result = self.buffer + self._read_limited()
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/wsgi.py", line 41, in _read_limited
    result = self.stream.read(size)
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 315, in read
    data = self.rfile.read(size)
  File "/usr/lib/python3.4/_pyio.py", line 962, in read
    return self._read_unlocked(size)
  File "/usr/lib/python3.4/_pyio.py", line 1006, in _read_unlocked
    chunk = self.raw.read(wanted)
  File "/usr/lib/python3.4/socket.py", line 371, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/base.py", line 187, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/base.py", line 185, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/views/decorators/csrf.py", line 58, in wrapped_view
    return view_func(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/viewsets.py", line 116, in view
    return self.dispatch(request, *args, **kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/views.py", line 495, in dispatch
    response = self.handle_exception(exc)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/views.py", line 455, in handle_exception
    self.raise_uncaught_exception(exc)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/views.py", line 483, in dispatch
    self.initial(request, *args, **kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/views.py", line 401, in initial
    self.check_permissions(request)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/views.py", line 334, in check_permissions
    if not permission.has_permission(request, self):
  File "/usr/lib/python3/dist-packages/kolibri/core/logger/permissions.py", line 52, in has_permission
    if request.data:
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/request.py", line 212, in data
    self._load_data_and_files()
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/request.py", line 275, in _load_data_and_files
    self._data, self._files = self._parse()
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/request.py", line 350, in _parse
    parsed = parser.parse(stream, media_type, self.parser_context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/parsers.py", line 68, in parse
    return json.load(decoded_stream, parse_constant=parse_constant)
  File "/usr/lib/python3/dist-packages/kolibri/dist/rest_framework/utils/json.py", line 34, in load
    return json.load(*args, **kwargs)
  File "/usr/lib/python3.4/json/__init__.py", line 265, in load
    return loads(fp.read(),
  File "/usr/lib/python3.4/codecs.py", line 486, in read
    newdata = self.stream.read()
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/http/request.py", line 334, in read
    six.reraise(UnreadablePostError, UnreadablePostError(*e.args), sys.exc_info()[2])
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/http/request.py", line 332, in read
    return self._stream.read(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/wsgi.py", line 47, in read
    result = self.buffer + self._read_limited()
  File "/usr/lib/python3/dist-packages/kolibri/dist/django/core/handlers/wsgi.py", line 41, in _read_limited
    result = self.stream.read(size)
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 315, in read
    data = self.rfile.read(size)
  File "/usr/lib/python3.4/_pyio.py", line 962, in read
    return self._read_unlocked(size)
  File "/usr/lib/python3.4/_pyio.py", line 1006, in _read_unlocked
    chunk = self.raw.read(wanted)
  File "/usr/lib/python3.4/socket.py", line 371, in readinto
    return self._sock.recv_into(b)
django.http.request.UnreadablePostError: timed out
WARNING 2020-02-05 01:35:31,193 cherrypy.error ENGINE socket.error 'cannot read from timed out object'
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 1156, in communicate
    req.respond()
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 974, in respond
    self.server.gateway(self).respond()
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/wsgi.py", line 138, in respond
    self.write(chunk)
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/wsgi.py", line 217, in write
    self.req.ensure_headers_sent()
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 1021, in ensure_headers_sent
    self.send_headers()
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 1087, in send_headers
    self.rfile.read(remaining)
  File "/usr/lib/python3/dist-packages/kolibri/dist/cheroot/server.py", line 315, in read
    data = self.rfile.read(size)
  File "/usr/lib/python3.4/_pyio.py", line 962, in read
    return self._read_unlocked(size)
  File "/usr/lib/python3.4/_pyio.py", line 1006, in _read_unlocked
    chunk = self.raw.read(wanted)
  File "/usr/lib/python3.4/socket.py", line 368, in readinto
    raise OSError("cannot read from timed out object")
OSError: cannot read from timed out object

Edit: Around the time of this exception traceback, there is a full minute of gap in the log, perhaps because Kolibri is unresponsive. Do you have any other log files that you could share, so we can see if this repeats?

Bruce · February 20, 2020, 9:22am

@benjamin here is the folder of our logs.

benjamin · February 20, 2020, 8:52pm

Hi @Bruce,

Thanks for sharing the remaining log files. I had a thorough look, but I can’t share anything conclusive, so these are my notes for now, prior to continuing tomorrow:

The logs show 1 exception accessing /api/logger/examattemptlog/e0d71a8104b3ee5a66d5d6d4d867a891/ but no other similar exceptions show up in any of the logs. This doesn’t really fit your description of something hanging several times? Unless you only did this test once on Feb 19th and once on Feb 5th?

So if this has happened many times, I wonder about other causes.

I’ll investigate once case where it seems that Kolibri waits (busy waits?) for 15 minutes to retry a ping request, and the log message is repeated every 2 minutes:

3064:WARNING 2020-02-19 06:33:43,390 utils Ping failed (could not connect). Trying again in 15 minutes.
3086:WARNING 2020-02-19 06:35:44,480 utils Ping failed (could not connect). Trying again in 15 minutes.
3280:WARNING 2020-02-19 06:37:45,941 utils Ping failed (could not connect). Trying again in 15 minutes.
3340:WARNING 2020-02-19 06:39:47,848 utils Ping failed (could not connect). Trying again in 15 minutes.
3348:WARNING 2020-02-19 06:41:49,297 utils Ping failed (could not connect). Trying again in 15 minutes.
3383:WARNING 2020-02-19 06:43:51,333 utils Ping failed (could not connect). Trying again in 15 minutes.
3390:WARNING 2020-02-19 06:45:53,025 utils Ping failed (could not connect). Trying again in 15 minutes.
3391:WARNING 2020-02-19 06:47:54,362 utils Ping failed (could not connect). Trying again in 15 minutes.

As an extra note: There is a problem in the way that requests are logged (only static requests show up, but not endpoints etc), that has to be fixed separately in Kolibri, I’ll see what can be done and file an issue if necessary. But to make the log analysis more fruitful, we need all GET requests for Django (including API endpoints) logged.

Rutayisire_Bruce · February 28, 2020, 2:07pm

Hello @benjamin!

We use Kolibri for class every Wednesday but before that instructors have to create quizzes and check exercise progress for students and each time they log on it they page loads really slowly. We have been facing this issue for a longtime.

As per your extra notes: Is there anything you want me to do. I am not a tech expert, I did not quite get what you meant by: “to make the log analysis more fruitful, we need all GET requests for Django (including API endpoints) logged.”

benjamin · February 29, 2020, 8:36pm

Hi @Rutayisire_Bruce

No need to worry about the latter message. I just cannot get to the bottom of analyzing the issue because important information is missing in the logs, but that’s not your fault.

It can be helpful of you can run Kolibri with --debug and then reproduce the crash/freeze and then send me the kolibri.txt log again.

From your Rachel Device, you need to run these commands from Command Line:

# Stop Kolibri
sudo service kolibri stop
# Log in as the kolibri user
sudo su -l `cat /etc/kolibri/username`
# Run kolibri with --debug
kolibri start --debug

To stop Kolibri after this, you press CTRL-C.

Please let me know if these commands work, I don’t unfortunately know if the Rachel intallation of Kolibri is differnet from other implementations, but I think it should be the same.

Thanks!

benjamin · March 5, 2020, 6:33pm

Dear @Rutayisire_Bruce ,

I have created a fix for the logging issue so it’s easier to see exactly which pages are accessed during an incident. I don’t know if the scenario is easy for you to recreate? But if you are able to download the .deb installer to a device from this link:

https://storage.googleapis.com/le-downloads/kolibri-release-13543-first-report.html

Note that this does not fix your issue, it can just help our understanding of what’s happening in Kolibri when you’re encountering the issue.

We’ll of course continue trying to find out what causes these freezes.

Best,
Ben

Topic		Replies	Views
Database locked error preventing startup [time sensitive] Kolibri	6	1017	August 22, 2023
Error message for coursework Support	1	219	February 16, 2023
Got the following error in Kolibri today: Kolibri	19	1438	June 29, 2020
After Upgrading to kolibri v0.11.1 - Server continues to disconnects and reconnects clients Kolibri	44	4477	February 13, 2019
Help Pls: Kolibri disconnecting and error "The server is starting.. please wait" Support	5	1254	March 6, 2019

Delay with the coach interface on Kolibri

Related Topics