Experimental SCORM host XBlock... and a possible race condition?
276 views
Skip to first unread message
Brad Smith
Sep 26, 2014, 12:28:36 PM9/26/14
to edx-...@googlegroups.com
Hello all,
THE SHORT VERSION:
I'm writing an xblock that can host content generated by tools that produce SCORM content objects (e.g. eXe, Articulate, etc), but it's encountering odd problems that seem to come up with you attempt to frequently update a Data field. I would love to get comments on the problem I'm having and/or the idea for the project in general. Github link at the bottom (but if you plan to mess with it, you should probably read this whole message) ;)
THE GORY DETAILS:
I wanted a project with which to learn about XBlocks, and decided to try making one that can host a SCORM content object (SCO). Coming from a corporate tech training department, the lack of SCORM support has always seemed to me to be a big barrier to adoption of the edX platform, since most of the industry-standard content creation tools (Articulate, Storyline, and free tools like Xerte and eXe) generate content that needs a SCORM-aware LMS for hosting. SCORM support in edX would bring with it the ability for people to deploy existing content, and develop new content using existing tools rather than requiring duplicate features in Studio.
Anyway.
The SCORM standard is notoriously complex, but I happened upon a relatively accessible reference, and decided to give it a shot.
(note: I'm implementing SCORM 1.2, since it seems to be the most consistently implemented in the tools I've seen)
Basically, a SCO is just HTML and Javascript, which expects whatever is hosting it to provide a js object called API, which implements calls that allow it to communicate with the host LMS.
So, I created a simple SCORM quiz using eXe, which I'm using as the student view of my xblock. Eventually I'm envisioning a studio view that would provide the ability to upload an arbitrary SCO, but we're not there yet.
The xblock's Javascript generates (most of) the expected SCORM API object in a way that uses the block's handlers to pass data between the SCO and python, mostly getting and setting certain SCORM properties.
The properties we care about most are cmi.core.score.raw (user's score on the test), and cmi.core.score.max (max possible score). These are what will eventually be used to construct the 'grades' value we'd publish to the runtime. It doesn't attempt to publish anything to its runtime yet, but there is a line to do it, just commented out for now.
The xblock stores all the SCORM data it gets from the courseware in a Dict field, self.scorm_data. Whenever the SCO wants to set a SCORM property value, it calls API.LMSSetValue(var,val), which in turn calls the scorm_set_value handler in Python. All scorm_set_value does is set self.scorm_data[var] = val. Maybe that's not how you're supposed to use Dict, but previously I tried getting a dict with self.scorm_data.read_from(self), modifying it, and then writing it back with self.scorm_data.write_to(self,updated_dict), and that produced 500 Server Errors, which no details printed anywhere I could see (so, side-question: how do you troubleshoot that kind of thing-- I've never seen Django 500 with no other error information).
Anyway, this is where I start having trouble. scorm_set_value updates self.scorm_data, and then returns a bunch of debug info that goes to the js console (and STDOUT in some cases-- yeah, bad I know), but the data I'm getting back are not what I expect to see.
Here's what I'm doing, and the odd behavior I'm seeing:
- Access the xblock from workbench
- Open the JS console
- In the console, run `API.scorm_clear()` # not needed the first time, but ensures there's no old data to confuse things
- Select one of the answers and submit
- Acknowledge the annoying popup that should be replaced by something else, but that's eXe's fault not mine ;)
- There should now be a ton of debug information in the console. Basically, every call to scorm_set_value() prints a timestamp, the data submitted to it, and the contents of self.scorm_data, both before AND after it stores the value (because it's returned as dictionary, the before an after values don't necessarily appear in order, but they're labeled).
- You can also run API.scorm_dump() to see the current contents of scorm_data
Here's an example of the logging output for one call to set_value():
Note: the syntax here is "Data returned from server: $timestamp (BEFORE|AFTER) SET {$given_data} = {$self.scorm_data}"
Data returned from server: 1411746297.05 BEFORE SET {u'cmi.interactions.0.correct_responses.0.pattern': u'0'} = {}
Data returned from server: 1411746297.05 AFTER SET {u'cmi.interactions.0.correct_responses.0.pattern': u'0'} = {u'cmi.interactions.0.correct_responses.0.pattern': u'0'} (index):1039Ok, so it starts with an empty scorm_data, and ends with one populated with the given value. Cool.
...but then here's what the next call reports. Note that it starts *after* the previous call, but thinks that self.scorm_data is empty when it starts!
Data returned from server: 1411746297.06 BEFORE SET {u'cmi.interactions.0.result': u'correct'} = {}
Data returned from server: 1411746297.07 AFTER SET {u'cmi.interactions.0.result': u'correct'} = {u'cmi.interactions.0.result': u'correct'} So maybe "race condition" isn't the right term, but suffice to say there seems to be something funky going on if you attempt to set a bunch of values in a Dict field in quick succession. The really odd thing is that settings don't always overwrite one another; some updates stick, some don't.
Unfortunately, the result of all this is that by the end of the submission process, if you run API.scorm_dump() again, you end up with what seems to be a random assortment of one or two of the seven or so things that SCORM wants to set, and until I can at least guarantee that the score.raw and score.max values stick, I don't have anything I can reliably publish to the runtime.
You can find the code, (which please remember is a learning project! ;) here:
Oh, one important note if you want to run the xblock yourself: you'll need to install the LXML module (pip install python-lxml). There's probably a more edX-y way to munge HTML, but I'm working with what I know for now.
Thanks to anyone who took the time to read all this! ;)
--Brad
Calen Pennington
Sep 26, 2014, 1:09:46 PM9/26/14
to edx-...@googlegroups.com
Re: self.scorm_data.read_from(self) might have worked, but you need to make sure you get the Field class, not the field data, so you'd need self.fields['scorm_data'] or self.__class__.scorm_data.
I'm guessing that you're using the xblock-sdk for your development. I'd be curious to know what the server logs for database queries while your handlers are running. You should be seeing a query that's pulling in the data for your XBlock at the beginning of the handler execution, and then writing your changes back to the database at the end of the handler execution.
-Cale
Brad Smith
Sep 27, 2014, 12:27:19 PM9/27/14
to edx-...@googlegroups.com
Thanks for the quick response!
Ok, looking in workbench.log...
So it looks like the `two` key got added, but then it was "forgotten" the next time `one` was updated. Sure enough, running `API.scorm_dump()` at this point shows scorm_data = { "one" : "wa'" }.
Now do updates to both of the existing keys and a new key in quick succession...
...and the logs get even weirder (##comments inline):
The debug data my functions log to the console also show that successive updates aren't aware of changes made by their successors (again, note that an "AFTER" may come before the corresponding "BEFORE" log):
Let's start with something simple. In the JS console I'll run:
API.LMSSetValue("one","one")This produces the following log:
(0.001) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)
(0.000) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "one"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one"\n }\n}', 281)That's more SELECTs than I would have expected, but the UPDATE at the end looks OK.
Now let's try something more challenging from the console...
var data = [["one","uno"],["one","eins"],["one","eens"],["two","dos"],["one","wa'"]]
for (var i in data) { API.LMSSetValue(data[i][0],data[i][1]) } ;Now I see this in the logs...
# Whooooole bunch of SELECTs, then...
(0.004) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "uno"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "uno"\n }\n}', 281)
(0.000) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)
(0.054) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)
(0.061) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "eens"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "eens"\n }\n}', 281)
(0.239) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "eins"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "eins"\n }\n}', 281)
## NOTE THIS BIT HERE. The "two" property is added, but then...
(0.421) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "one",
"two": "dos"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one",\n "two": "dos"\n }\n}', 281)
## ...in the next operation, it's gone.
(0.465) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "wa'"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "wa\'"\n }\n}', 281)
So it looks like the `two` key got added, but then it was "forgotten" the next time `one` was updated. Sure enough, running `API.scorm_dump()` at this point shows scorm_data = { "one" : "wa'" }.
I wonder if this problem only applies to new keys. Ok, I'll reset everything with `API.scorm_clear()`, and start with two keys:
API.LMSSetValue("one","one")
API.LMSSetValue("two", "two")So far the log looks ok:
(0.000) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "one" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one"\n }\n}', 281)
(0.000) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "one", "two": "two" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one",\n "two": "two"\n }\n}', 281)Now do updates to both of the existing keys and a new key in quick succession...
var data = [["one","uno"],["one","eins"],,["two","dos"],["three","tres"],["one","wa'"]]
for (var i in data) { API.LMSSetValue(data[i][0],data[i][1]) } ;
...and the logs get even weirder (##comments inline):
## Updating "one" to "uno": looks good
(0.004) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "uno", "two": "two" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "uno",\n "two": "two"\n }\n}', 281)(0.003) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')(0.001) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)(0.000) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)(0.044) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)
## Huh. Updating "two" to "dos" was the *third* update issued, not the second, AND the value of "one" got reverted (0.074) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "one", "two": "dos" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one",\n "two": "dos"\n }\n}', 281)
## Then we update "one" to "eins" (second command issued), and "two" reverts!(0.556) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "eins", "two": "two" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "eins",\n "two": "two"\n }\n}', 281)
## Now the fifth update issued happens. "two" is still its original value.(0.925) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "wa'", "two": "two" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "wa\'",\n "two": "two"\n }\n}', 281)
## The fourth operation, adding a "three" key, lands last... and now "one" is reverted, too.(1.294) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = { "scorm_data": { "one": "one", "three": "tres", "two": "two" }} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one",\n "three": "tres",\n "two": "two"\n }\n}', 281)The debug data my functions log to the console also show that successive updates aren't aware of changes made by their successors (again, note that an "AFTER" may come before the corresponding "BEFORE" log):
Data returned from server: 1411834063.46 AFTER SET {u'one': u'uno'} = {u'two': u'two', u'one': u'uno'} (index):1039Data returned from server: 1411834063.46 BEFORE SET {u'one': u'uno'} = {u'two': u'two', u'one': u'one'} (index):1039Data returned from server: 1411834063.47 AFTER SET {u'two': u'dos'} = {u'two': u'dos', u'one': u'one'} (index):1039Data returned from server: 1411834063.47 BEFORE SET {u'two': u'dos'} = {u'two': u'two', u'one': u'one'} (index):1039Data returned from server: 1411834063.47 AFTER SET {u'one': u'eins'} = {u'two': u'two', u'one': u'eins'} (index):1039Data returned from server: 1411834063.47 BEFORE SET {u'one': u'eins'} = {u'two': u'two', u'one': u'one'} (index):1039Data returned from server: 1411834063.48 AFTER SET {u'one': u"wa'"} = {u'two': u'two', u'one': u"wa'"} (index):1039Data returned from server: 1411834063.47 BEFORE SET {u'one': u"wa'"} = {u'two': u'two', u'one': u'one'} (index):1039Data returned from server: 1411834063.47 AFTER SET {u'three': u'tres'} = {u'three': u'tres', u'two': u'two', u'one': u'one'} (index):1039Data returned from server: 1411834063.47 BEFORE SET {u'three': u'tres'} = {u'two': u'two', u'one': u'one'} I'll keep digging into this, but anyone have ideas?
--Brad
P.S. Quick side-note/question about workbench.log: there seems to be something funky about the way the server flushes logs to this file; I'd tried following it with `tail -f` before, but thought it wasn't logging anything. It turns out that while sometimes logs appear in the tail output immediately, sometimes there's a longish delay, and sometimes they just stop showing up altogether, and I have to kill and restart tail to see them-- has anyone else encountered this?
Brad Smith
Nov 12, 2014, 11:58:21 AM11/12/14
to edx-...@googlegroups.com
Well, I've ended up finding a workaround, though I'm not sure exactly how terrible it is.
Here's the short version, on which I would like opinions if people have them. Then I'll go into some more detail for those who care. The solution I found that works is:
- Create an instance of lock.Lock as a class property of the xblock (could probably, and probably should, do this as class property of a custom field type instead, now that I think about it more)
- When writing to the field, acquire the lock, write directly to _field_data (bypassing cache!), then release the lock.
@XBlock.json_handler
def scorm_set_value(self, data, suffix=''):
self.lock.acquire()
try:
scorm_data = self._field_data.get(self,"scorm_data")
except KeyError:
scorm_data = {}
scorm_data.update(data)
self._field_data.set(self,"scorm_data", scorm_data)
self.lock.release()
So I guess my main questions are: how much does bypassing the cache like this make people cringe, and does anyone see any better solutions I've just missed?
A little more on what I've learned about the problem...
The "race condition" I described earlier in this thread happens if you do multiple AJAX calls in quick succession (and in my case preventing this is difficult since that's valid behavior according to SCORM). Each call is handled by a different instance of your XBlock class, each of which writes to its own _field_data_cache dict (which, unlike _field_data, is an instance property, not a class property). That should be fine, but the values you're writing are all supposed to merge into a single Dict field, it all goes wrong when the caches sync back to the runtime's KVS. I've only partially figured out all the mechanics at work here, but I think it's as simple as each cached field overwriting instead of updating (as in {}.update()) its previous value. In other words, you end up with one instance of your XBlock per API call, each of which has its own instance of the Dict field, each of which has its own _field_data_cache. When a sync happens, whichever instance gets saved last replaces the entire field value in the runtime's data store with whatever is in its cache. Hence why forcing them to update (with an actual .update() the field's value in _field_data directly one at a time solves the problem.
I think the next time I have time to mess with this I'm going to try to move all the locking stuff from the XBlock to the field, so it's all done transparently in the field's __set__(). That way everything is in a re-usable LockingDict (or whatever) field type.
(oh, and if anyone is wondering why I don't just create a separate field for each SCORM property instead of using a Dict, well aside from there being a *lot* of them in a full implementation of SCORM, several of them have arbitrary names, incorporating things like a question number, for example, so afaik that means using separate fields is a no-go for this use case)
It's also been suggested that this might point to the need for a more flexible implementation of KeyValueStore to be integrated into each of the runtimes, but.. that's a bit more than I'm prepared to deal with at the moment.
Ok, one last thing to wrap up: this has been a journey down a very, very deep rabbit hole, but it was also very educational, both about the inner workings of Xblock fields and about some Python features I'd never dealt with before, like @property, __get__ and __set__. At one point I went a little nuts a wrote some wrapper classes to try and log as much pertinent information as I could get about what actually happens when you write to a field. I've put an example of the resulting activity log up here. If someone else finds it helpful, I'll feel a little more like it was worth staying up way past my bedtime a couple of nights. ;)
--Brad
On Saturday, September 27, 2014 12:27:19 PM UTC-4, Brad Smith wrote:
Thanks for the quick response!
Ok, looking in workbench.log...Let's start with something simple. In the JS console I'll run:
(0.000) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT "workbench_xblockstate"."id", "workbench_xblockstate"."scope", "workbench_xblockstate"."scope_id", "workbench_xblockstate"."user_id", "workbench_xblockstate"."scenario", "workbench_xblockstate"."tag", "workbench_xblockstate"."created", "workbench_xblockstate"."state" FROM "workbench_xblockstate" WHERE ("workbench_xblockstate"."scope" = usage AND "workbench_xblockstate"."tag" = xb_scorm AND "workbench_xblockstate"."scope_id" = xblockscorm.xb_scorm.d0.u0 AND "workbench_xblockstate"."scenario" = xblockscorm AND "workbench_xblockstate"."user_id" = student_1 ); args=('usage', u'xb_scorm', u'xblockscorm.xb_scorm.d0.u0', u'xblockscorm', u'student_1')
(0.000) SELECT (1) AS "a" FROM "workbench_xblockstate" WHERE "workbench_xblockstate"."id" = 281 LIMIT 1; args=(281,)
(0.000) UPDATE "workbench_xblockstate" SET "scope" = usage, "scope_id" = xblockscorm.xb_scorm.d0.u0, "user_id" = student_1, "scenario" = xblockscorm, "tag" = xb_scorm, "created" = 2014-09-26 15:02:30.212505, "state" = {
"scorm_data": {
"one": "one"
}
} WHERE "workbench_xblockstate"."id" = 281 ; args=(u'usage', u'xblockscorm.xb_scorm.d0.u0', u'student_1', u'xblockscorm', u'xb_scorm', u'2014-09-26 15:02:30.212505', '{\n "scorm_data": {\n "one": "one"\n }\n}', 281)That's more SELECTs than I would have expected, but the UPDATE at the end looks OK.Now let's try something more challenging from the console...
for (var i in data) { API.LMSSetValue(data[i][0],data[i][1]) } ;Now I see this in the logs...
...
"scorm_data"<span style="color: #660;" class="s
Reply all
Reply to author
Forward
0 new messages