Cannot insert into numbas_lti_scormelement for exams with score

baotn166 commented 4 years ago

Hi everyone,

Currently, I got this issue when inserting into numbas_lti_scormelement. This is the logs for the insert query:

(0.001) INSERT INTO "numbas_lti_scormelement" ("attempt_id", "key", "value", "time", "counter", "current") VALUES (711, 'cmi.score.scaled', '0.022727272727272728', '2020-06-15T10:19:29.376000+00:00'::timestamptz, 507, true) RETURNING "numbas_lti_scormelement"."id"; args=(711, 'cmi.score.scaled', '0.022727272727272728', datetime.datetime(2020, 6, 15, 10, 19, 29, 376000, tzinfo=<UTC>), 507, True)

Because of this, this request takes long time and it reaches the nginx timeout (15m)

And after 15mins

Note that: I can run the query directly into postgres db. I'm just not sure this is a bug or did I do something wrong when setting up the entire numbaslti system.

Thanks for your support.

christianp commented 4 years ago

@baotn166 I can't think what would cause that. Does any data at all get saved into that table, or does it always fail?

baotn166 commented 4 years ago

@christianp there are records in that table. And noted that I can save exams that don't have any scores. For the exam which started at June 15, 2020, 9:30 a.m, I just clicked "submit all parts" then "End exam" and I can see the button "Review this attempt". For the other exams, I answered at least 1 correct question then clicked "submit all parts" then "End exam" and the red notification showed (Attempt data is being saved to the database. Please wait.) I'm not sure if there's anything of websocket involved in this process (submit all parts & End exam). And I can see the post method is calling when ending the exam and that request reaches the nginx timeout

baotn166 commented 4 years ago

I have some hints for this issue:

the plugin uses transaction in django.db

when I submit a correct answer, then click submit part, there is no RELEASE SAVEPOINT according to this transaction

(0.000) SAVEPOINT "s140072378541888_x8"; args=None
(0.000) INSERT INTO "numbas_lti_scormelement" ("attempt_id", "key", "value", "time", "counter", "current") VALUES (717, 'cmi.score.scaled', '0.022727272727272728', '2020-06-16T07:41:15.741000+00:00'::timestamptz, 508, true) RETURNING "numbas_lti_scormelement"."id"; args=(717, 'cmi.score.scaled', '0.022727272727272728', datetime.datetime(2020, 6, 16, 7, 41, 15, 741000, tzinfo=<UTC>), 508, True)

If this query got hung, I couldn't do actions such as "Submit all parts", "End exam"

Important note: the numbas lti server can load data, even can save an attempt with no answer.

christianp commented 4 years ago

This is very hard to debug remotely. I think it has to be to do with your postgres configuration, but I don't know where you could start looking.

baotn166 commented 4 years ago

@christianp I'm using Postgres RDS. Is there any param I should change to fix the issue?

christianp commented 4 years ago

Sorry, I don't know.

baotn166 commented 4 years ago

@christianp Do you need any more information for this? I can give you if it could help. Thanks

christianp commented 3 years ago

It might be that the problem isn't saving the score to the database, it's reporting the score back to the VLE. Can you try changing the "When to report scores back" setting for the resource to "Manually by instructor", and see if the error still happens?

baotn166 commented 3 years ago

@christianp I will check then let you know soon. Thanks

baotn166 commented 3 years ago

@christianp I got this message when applying the change you suggested

baotn166 commented 3 years ago

and when I went to the course, I got this So I'm just not sure is it working as expected or not

christianp commented 3 years ago

That looks OK to me.

baotn166 commented 3 years ago

@christianp I can see these requests back to vle site

10.224.2.131 - - [07/Oct/2020:09:18:14 +0000] "GET /mod/lti/service.php HTTP/1.1" 200 363 "-" "python-requests/2.21.0" - 0.037 X-Forwarded-For=52.17.244.115 Host=hvle1gb.com 0a96e0c289386ba560dda8aa7840b
10.224.7.172 - - [07/Oct/2020:09:18:33 +0000] "POST /mod/lti/service.php HTTP/1.1" 200 365 "-" "python-requests/2.21.0" - 0.067 X-Forwarded-For=52.17.244.115 Host=hvle1gb.com da0823b6de0df3d56a1c5d00741e2
10.224.2.131 - - [07/Oct/2020:09:18:49 +0000] "POST /mod/lti/service.php HTTP/1.1" 200 367 "-" "python-requests/2.21.0" - 0.046 X-Forwarded-For=52.17.244.115 Host=hvle1gb.com 0262b5635bd8482185c8fdb9968af
10.224.7.172 - - [07/Oct/2020:09:19:07 +0000] "GET /mod/lti/service.php HTTP/1.1" 200 362 "-" "python-requests/2.21.0" - 0.030 X-Forwarded-For=52.17.244.115 Host=hvle1gb.com 86a304b70d190638e3cc537098cd8
10.224.7.172 - - [07/Oct/2020:09:20:26 +0000] "GET /mod/lti/service.php HTTP/1.1" 200 697 "-" "curl/7.29.0" - 0.035 X-Forwarded-For=52.17.244.119 Host=hvle1gb.com 434069b6d32b66b4faff2f0aecf7a
10.224.7.172 - - [07/Oct/2020:09:22:17 +0000] "POST /mod/lti/service.php HTTP/1.1" 200 367 "-" "python-requests/2.21.0" - 0.094 X-Forwarded-For=52.17.244.115 Host=hvle1gb.com 79f287be1776488b460abbca6df80

However the blue message box is still showing

So I'm not sure if it's working or not

christianp commented 3 years ago

Can you try doing report_outcome from the shell again, and see what it does?

numbas / numbas-lti-provider

Cannot insert into numbas_lti_scormelement for exams with score #91