Delay with the coach interface on Kolibri

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 ]

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?

@benjamin here is the folder of our logs.

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.