AssertionError at /api/videolog/ for guest user

[critch]

Summary

When viewing a video on a RHEL system with pip install KALite 0.17.1, a request is made to /api/videolog that results in a 500 error. This error when viewed from a tablet results in an overlay on the video that causes the video controls to no longer be accessible. There are actually many ways to trip the videolog call such as skipping around in the video. End result is always a 500 error.

System information

• Operating system: RHEL 7.2
• Version: 0.17.1
• Browser: Many, Chrome on desktop, Crosswalk on Android. Not browser dependent.

Traceback or relevant snippet from server.log

May 17 17:23:08 host uwsgi: [ERROR] [2017-05-17 17:23:08,677] kalite: Failed to update userlog during video: [u'A valid user must always be specified.']
May 17 17:23:08 host uwsgi: [ERROR] [2017-05-17 17:23:08,709] django.request.tastypie: Internal Server Error: /api/videolog/
May 17 17:23:08 host uwsgi: Traceback (most recent call last):
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 195, in wrapper
May 17 17:23:08 host uwsgi: response = callback(request, *args, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 426, in dispatch_list
May 17 17:23:08 host uwsgi: return self.dispatch('list', request, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 458, in dispatch
May 17 17:23:08 host uwsgi: response = method(request, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 1320, in post_list 
May 17 17:23:08 host uwsgi: updated_bundle = self.obj_create(bundle, **self.remove_api_resource_names(kwargs))
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 2084, in obj_create
May 17 17:23:08 host uwsgi: return self.save(bundle)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/tastypie/resources.py", line 2230, in save
May 17 17:23:08 host uwsgi: bundle.obj.save()
May 17 17:23:08 host uwsgi: File "/usr/lib/python2.7/site-packages/kalite/main/models.py", line 80, in save
May 17 17:23:08 host uwsgi: super(VideoLog, self).save(*args, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/securesync/engine/models.py", line 478, in save 
May 17 17:23:08 host uwsgi: super(DeferredCountSyncedModel, self).save(*args, increment_counters=increment_counters, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/securesync/engine/models.py", line 456, in save
May 17 17:23:08 host uwsgi: super(DeferredSignSyncedModel, self).save(*args, sign=sign, **kwargs)
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/securesync/engine/models.py", line 381, in save 
May 17 17:23:08 host uwsgi: self.set_id()
May 17 17:23:08 host uwsgi: File "/usr/share/kalite/python-packages/securesync/engine/models.py", line 481, in set_id
May 17 17:23:08 host uwsgi: self.id = self.id or self.get_uuid()
May 17 17:23:08 host uwsgi: File "/usr/lib/python2.7/site-packages/kalite/main/models.py", line 83, in get_uuid
May 17 17:23:08 host uwsgi: assert self.user is not None and self.user.id is not None, "User ID required for get_uuid"
May 17 17:23:08 host uwsgi: AssertionError: User ID required for get_uuid
May 17 17:23:08 host uwsgi: [INFO] [2017-05-17 17:23:08,713] django.request: HTTP Request /api/videolog/ - Response: 500
May 17 17:23:08 host uwsgi: [pid: 1038|app: 0|req: 50/709] 10.1.10.7 () {58 vars in 1369 bytes} [Wed May 17 17:23:08 2017] POST /api/videolog/ => generated 88 bytes in 186 msecs (HTTP/1.0 500) 3 headers in 123 bytes (1 switches on core 0)

How to reproduce

1. do not log in
2. click learn
3. progress to a video
4. play video to completion
5. Observe error

Real-life consequences (anything community should be aware, for instance how it affects your deployment)

When this bug is tripped, it results in inaccessible video player controls on tablets. If triggered via skipping around, the video could be playing under the error message with no ability to stop the player.

[benjaoming]

Thanks for debugging and reporting this @critch - this could perhaps explain some odd experiences with the video player.

In case you are able to work on the issue, we'll be there for any kind of assistance!

Otherwise we'll have someone look at it so it's fixed no later than 0.17.3 (since we better release the other one really soon).

[critch]

I'm not really a Python person. I'm just enough of a tech and developer to get you the good info.

[mrpau-eugene]

hi @critch .. May I ask if this is problem is specific to RHEL 7.2? I wanted to gather more information regarding to this issue.

I also tried to reproduce this on Mac from the steps you've given. Tried both Google Chrome and Firefox but the logs weren't giving me those kind of errors.

[mrpau-eugene]

I happen to find a similar issue regarding with this current issue: API error after watching a video. #4957 and 'User ID required for get_uuid' error at the end of video for non logged in users #4073

@benjaoming mentioned that @jamalex fixed this before. Would you mind explaining what was causing this and how you fixed this issue? Thanks!

[benjaoming]

@mrpau-eugene sorry can't recall what I recalled back then. I've reopened #4957, try reproducing by having an admin user logged in?

Closing this as a duplicate then...

[mrpau-eugene]

@benjaoming have tried those already but I was still unable to reproduce it. I saw someone fixed it by adding !window.statusModel.get("is_admin) in the close function. I'm just wondering why it's still occurring.

close: function() {
        if (window.statusModel.get("is_logged_in") && !window.statusModel.get("is_admin") ) {
            this.log_model.saveNow();
        }
        this.remove();
    }

Maybe there were console errors appearing in the author's browser which might help..

[critch]

This does appear to be a duplicate of the mentioned items.

[mrpau-eugene]

@critch yes.. however the previous issues experienced this when logged in as administrator..

By the way, are there any errors in the console when you experienced this issue?