Interpreting SCORM API Debugging logs help

Interpreting SCORM API Debugging logs help

by Mathew Gancarz -
Number of replies: 6
Picture of Core developers

Hi everyone, I've been trying to track down an issue that occasionally happens with our SCORM packages in our Moodle site. They work fine for most people, but occasionally will start throwing LMSGetValue errors. The modules work otherwise fine.

I was able to get one of our learners to open the module with API Debugging turned on, and got the following log. The person did not have any issues until they had left the SCORM activity up for several hours. When they returned they got a timeout and had to log back in. When they did they started getting the errors. I noticed the cmi.core.session_time showing up as 216 hours, so I'm guessing that means their SCORM session is somehow stuck open?

SCORM API Activity Log

Wed, 19 Mar 2014 19:53:46 GMT: Moodle SCORM 1.2 API Loaded, Activity: Module Three - Normal Lab Values, SCO: I_A001

Wed, 19 Mar 2014 19:53:50 GMT: LMSSetValue("cmi.core.lesson_location", "a001_welcome.html") => 301

Wed, 19 Mar 2014 19:53:50 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:21 GMT: LMSSetValue("cmi.core.lesson_location", "a001_table_of_contents.html") => 301

Wed, 19 Mar 2014 19:54:21 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:27 GMT: LMSSetValue("cmi.core.lesson_location", "a001_1._introduction.html") => 301

Wed, 19 Mar 2014 19:54:27 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:37 GMT: LMSSetValue("cmi.core.lesson_location", "a001_13._summary.html") => 301

Wed, 19 Mar 2014 19:54:37 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:43 GMT: LMSSetValue("cmi.core.lesson_status", "completed") => 301

Wed, 19 Mar 2014 19:54:43 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:46 GMT: LMSCommit("", "") => 0

Wed, 19 Mar 2014 19:54:46 GMT: LMSGetErrorString("301", "Not initialized") => 0

Wed, 19 Mar 2014 19:54:50 GMT: LMSSetValue("cmi.core.session_time", "216:51:01") => 301

Wed, 19 Mar 2014 19:54:50 GMT: LMSGetErrorString("301", "Not initialized") => 0

 

Here is the same module, this time logging in as me without any errors:

SCORM API Activity Log

Wed, 19 Mar 2014 20:10:45 GMT: Moodle SCORM 1.2 API Loaded, Activity: Module Three - Normal Lab Values, SCO: I_A001
Wed, 19 Mar 2014 20:10:46 GMT: LMSInitialize("", "") => 0
Wed, 19 Mar 2014 20:10:46 GMT: LMSGetValue("cmi.core.lesson_status") - completed => 0
Wed, 19 Mar 2014 20:10:46 GMT: LMSGetValue("cmi.core.lesson_location") - a001_1._introduction.html => 0
Wed, 19 Mar 2014 20:10:48 GMT: LMSSetValue("cmi.core.lesson_location", "a001_welcome.html") => 0
Wed, 19 Mar 2014 20:10:49 GMT: LMSSetValue("cmi.core.lesson_location", "a001_table_of_contents.html") => 0
Wed, 19 Mar 2014 20:10:50 GMT: LMSSetValue("cmi.core.lesson_location", "a001_1._introduction.html") => 0
Wed, 19 Mar 2014 20:10:52 GMT: LMSSetValue("cmi.core.lesson_location", "a001_13._summary.html") => 0
Wed, 19 Mar 2014 20:10:52 GMT: LMSSetValue("cmi.core.lesson_status", "completed") => 0
Wed, 19 Mar 2014 20:10:52 GMT: Commit("", "") => 0
Wed, 19 Mar 2014 20:10:52 GMT: LMSCommit("AJAXResult", "true") => 0
Wed, 19 Mar 2014 20:10:52 GMT: LMSCommit("result", "true") => 0
Wed, 19 Mar 2014 20:10:52 GMT: LMSCommit("errorCode", "0") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSSetValue("cmi.core.session_time", "00:00:08") => 0
Wed, 19 Mar 2014 20:10:54 GMT: Commit("", "") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSCommit("AJAXResult", "true") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSCommit("result", "true") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSCommit("errorCode", "0") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSFinish("AJAXResult", "true") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSFinish("result", "true") => 0
Wed, 19 Mar 2014 20:10:54 GMT: LMSFinish("", "") => 0
Average of ratings: -
In reply to Mathew Gancarz

Re: Interpreting SCORM API Debugging logs help

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Hi Mathew,
the difference is the missing of LMSInitialize() which is mandatory and must be the very first call before any other SCORM call during a (new) SCORM tracking session.

What could be the reason for that? It depends on the way the Tracking Logics has been coded into the Content but also on the Network Connectivity: if the network is not stable, it could be not possible to complete the callback behind LMSInitialize(), on the server. Another issue is the Moodle Logged-In Session Timeout which prevents the SCORM callback to be executed on the server but again that call would be tracked in the API Logging, not the case above.

The first improvement is to define a boolean which gives info about the SCORM tracking session being correctly opened after a successful call of LMSInitialize(); otherwise, any other call will be prevented and the user should be informed that the current "learning" session has been started without any chance of being tracked or, better, some retrying logics should take place.
The real fix depends on your Content.

About the long time being "recorded": the counter is running client side, in the Content, i.e. without the need of any authentication, just keeping the Content opened in the browser.

HTH,
Matteo

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Interpreting SCORM API Debugging logs help

by Mathew Gancarz -
Picture of Core developers

Thank you Matteo, I had the chance to run an experiment, essentially leaving the SCORM module open overnight to make sure that I was logged out of Moodle due to the session inactivity timeout.

When I came back and clicked to login again, I got the missing scoid error from Moodle since obviously the session had changed. Now when I go to re-open the module, the same thing occurs. Below is the entire beug log, including when I went back in.

SCORM API Activity Log

Wed, 19 Mar 2014 20:48:04 GMT: Moodle SCORM 1.2 API Loaded, Activity: Module Three - Normal Lab Values, SCO: I_A001
Wed, 19 Mar 2014 20:48:05 GMT: LMSInitialize("", "") => 0
Wed, 19 Mar 2014 20:48:05 GMT: LMSGetValue("cmi.core.lesson_status") - incomplete => 0
Wed, 19 Mar 2014 20:48:05 GMT: LMSGetValue("cmi.core.lesson_location") - a001_3._laboratory_testing.html => 0
Wed, 19 Mar 2014 20:48:25 GMT: LMSSetValue("cmi.core.lesson_location", "a001_welcome.html") => 0
Wed, 19 Mar 2014 20:48:25 GMT: LMSSetValue("cmi.core.lesson_location", "a001_3._laboratory_testing.html") => 0
Wed, 19 Mar 2014 20:48:28 GMT: LMSSetValue("cmi.core.lesson_location", "a001_4._complete_blood_count.html") => 0
Wed, 19 Mar 2014 20:48:32 GMT: LMSSetValue("cmi.core.lesson_location", "a001_5._white_blood_cell_count_wbc_or_leukocyte_count_.html") => 0
Thu, 20 Mar 2014 14:02:58 GMT: LMSSetValue("cmi.core.lesson_location", "a001_6._white_blood_cell_count_review_exercise.html") => 0
Thu, 20 Mar 2014 14:03:02 GMT: LMSSetValue("cmi.core.session_time", "17:14:57") => 0
Thu, 20 Mar 2014 14:03:39 GMT: Moodle SCORM 1.2 API Loaded, Activity: Module Three - Normal Lab Values, SCO: I_A001
Thu, 20 Mar 2014 14:03:40 GMT: LMSSetValue("cmi.core.lesson_location", "a001_welcome.html") => 301
Thu, 20 Mar 2014 14:03:40 GMT: LMSGetErrorString("301", "Not initialized") => 0
Thu, 20 Mar 2014 14:03:47 GMT: LMSSetValue("cmi.core.lesson_location", "a001_table_of_contents.html") => 301
Thu, 20 Mar 2014 14:03:47 GMT: LMSGetErrorString("301", "Not initialized") => 0
Thu, 20 Mar 2014 14:05:29 GMT: LMSSetValue("cmi.core.session_time", "17:17:24") => 301
Thu, 20 Mar 2014 14:05:29 GMT: LMSGetErrorString("301", "Not initialized") => 0
 
Note how the session_time did not reset when I went back in again at 14:03:39 GMT
 
Our SCORM content is created in Lectora Inspire 11.4, so I'm guessing the boolean you are talking about would have to be implemented using Lectora.
 
I also found this post on the Lectora forums: https://lectora.com/forum/showthread.php?t=11561&p=43748&viewfull=1#post43748 
If I understand, it would ping the LMS periodically to prevent the session from timing out.
 
Average of ratings: -
In reply to Mathew Gancarz

Re: Interpreting SCORM API Debugging logs help

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Hi Mathew,
yes, the boolean should stay in the content built with Lectora, to warn the users, and yes, the ping strategy could solve your issue even if it will add load to your instance since the Moodle session will be longer than the default value even if no human will be in front of a browser opened on a SCORM package.

BTW, I hope to be able to find some spare time to test it by myself: there's nothing that Moodle can do here but I want to understand why the API logging "reloads" itself - probably due to your navigating away from the current page, towards a new one, being the Moodle session expired.

FYI, about network failures: please, read MDL-28261 for the only improvement that can be coded on Moodle.

HTH,
Matteo

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Interpreting SCORM API Debugging logs help

by Mathew Gancarz -
Picture of Core developers

Hi Matteo, thank you, I think I understand now.

For your testing, the log above shows where I had left the SCORM window open overnight and when I came in the next morning, clicked on the next page button. I think at that point it threw me out of Moodle but I don't recall 100%. I then logged back into Moodle and re-opened the same SCORM package.

I've also tested wiping local cookies, it looks like it does not quite work the same way as a session timeout, Moodle forces me to log in again but the SCORM package isn't stuck open.

 

Average of ratings: -
In reply to Mathew Gancarz

Re: Interpreting SCORM API Debugging logs help

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Hi Mathew,
FYI MDL-28261 landed into the 2.7 version big grin and, probably, will land in  2.6 and 2.5 too: please follow MDL-44913.

HTH,
Matteo

Average of ratings: -