State API requires eTags (should be optional)

[garemoko]

Version Latest from composer as 22nd Jan 2015

Steps to reproduce the bug

1. Store an application/json document in the State API.
2. Update the document (PUT) omitting the etag header.

Expected behaviour Document should be accepted, returning 204 no content. Etags are not required for the State API, only the Agent and Activity Profile APIs.

Actual behaviour 400 Bad request is returned.

Server information MongoDB with Basic auth. Running on MAMP.

Client information OS: OS X 10.10.1 Browser: Chrome

Additional information I've tested the client code I'm using against Wax and Cloud and it works.

[davidpesce]

Getting really good at new installs. Ha.

Unfortunately, I'm still getting a 412.

Error attempting to set registration data to State API.

array(4) {
  ["contents"]=>
  bool(false)
  ["metadata"]=>
  NULL
  ["code"]=>
  array(13) {
    [0]=>
    string(32) "HTTP/1.0 412 Precondition Failed"
    [1]=>
    string(35) "Date: Wed, 25 Feb 2015 16:03:24 GMT"
    [2]=>
    string(39) "Server: Apache/2.4.6 (CentOS) PHP/5.6.4"
    [3]=>
    string(19) "Vary: Authorization"
    [4]=>
    string(23) "X-Powered-By: PHP/5.6.4"
    [5]=>
    string(39) "Cache-Control: private, must-revalidate"
    [6]=>
    string(16) "pragma: no-cache"
    [7]=>
    string(11) "expires: -1"
    [8]=>
    string(31) "X-Experience-API-Version: 1.0.1"
    [9]=>
    string(399) "Set-Cookie: laravel_session=eyJpdiI6IlNTSDNvemx5cmxIeGV0bDdlR3ZoTlU3d2lwRzdZQWpDdzExY0xxckFuU0E9IiwidmFsdWUiOiJIN245cHRENnBEUHlZU3JrK1ViRjFseTJTWFFRNWNLK2RUcUl4dHV4cXd4R21kNE1XN1poVXZpeVRjRXYyb3Q0U3RHeTdMRTdkZU43c3pCalZudDZrdz09IiwibWFjIjoiYmNiY2FiZDgzMTJmNmE2MWUxZGI3NTU0ZjE4Yzc5NWY4YmI1NjA5MzgwMWYwYTk3MWUwMmM0NWU0OGQ2NGI3MyJ9; expires=Wed, 25-Feb-2015 18:03:25 GMT; Max-Age=7200; path=/; httponly"
    [10]=>
    string(20) "Content-Length: 3935"
    [11]=>
    string(17) "Connection: close"
    [12]=>
    string(30) "Content-Type: application/json"
  }
  ["EtagHeader"]=>
  string(53) "If-Match : "2BE88CA4242C76E8253AC62474851065032D6833""
}

[ryasmi]

Haha. Can you clear you app/storage/laravel.log and then rerun your tests and tell me what you get in the laravel.log?

[davidpesce]

Oddly, there isn't a laravel.log in that location. Permissions are correct for that directly (apache) as well.

[ryasmi]

Are you able to send me your requests (headers, body, url - with params) in the order that they're sent? I'm going to try to reproduce the issue in Postman.

[davidpesce]

Gotta jet for a bit, but here's what I have:

Stream Options:

array(2) {
  ["ssl"]=>
  array(1) {
    ["verify-peer"]=>
    bool(false)
  }
  ["http"]=>
  array(4) {
    ["method"]=>
    string(3) "PUT"
    ["ignore_errors"]=>
    bool(false)
    ["header"]=>
    array(5) {
      [0]=>
      string(129) "Authorization: Basic ZWY1OTEyYmY1NTk1YTIwM2UyNzgxNWZkYjNhZDk0NjAwODE3MTM2ZDo5MGZlOGNmMmY4ZTBjYzNhNGUzYjU2Njk1NzFlYmI1ZDBiNGRhMjI4"
      [1]=>
      string(30) "Content-Type: application/json"
      [2]=>
      string(37) "Accept: application/json, */*; q=0.01"
      [3]=>
      string(31) "X-Experience-API-Version: 1.0.0"
      [4]=>
      string(53) "If-Match : "2BE88CA4242C76E8253AC62474851065032D6833""
    }
    ["content"]=>
    string(123) "{"4da8f30c-8f68-45ce-8cf5-284430bf0d65":{"created":"2015-02-25T11:25:59-05:00","lastlaunched":"2015-02-25T11:25:59-05:00"}}"
  }
}

StreamParameters:

array(3) {
  ["activityId"]=>
  string(50) "http://lrs.scrubbed.com/golf/index.html"
  ["agent"]=>
  string(90) "{"name":"Admin User","mbox":"mailto:support@scrubbed.com","objectType":"Agent"}"
  ["stateId"]=>
  string(49) "http://tincanapi.co.uk/stateapikeys/registrations"
}

Request:

http://lrs.scrubbed.com/data/xAPI/statements?activityId=http://lrs.scrubbed.com/golf/index.html&agent={"name":"Admin User","mbox":"mailto:support@scrubbed.com","objectType":"Agent"}&stateId=http://tincanapi.co.uk/stateapikeys/registrations

[ryasmi]

No worries, thanks for that.

[ryasmi]

Ok I've just tested that and my ETag was different. It all works as expected though from what I can see. It also passes the conformance tests.

[davidpesce]

Wouldn't the etag be different based on the LRS you're submitting to?

[davidpesce]

Deleted the database and started from scratch on conformance branch. First launch works fine. Second launch has the issue. ETag matches what's in the mongo db.

[ryasmi]

I thought the ETag would be the same, maybe I'm wrong.

That's so odd! This issue is crazy. I can't reproduce the damn thing.

[davidpesce]

I'm back at it now, but from the standpoint of seeing what's difference in the conformance branch from before.

I don't think it's the quotes, because I've tried stripping them and get the same results.

[ryasmi]

Yeah I agree, however, is it possible that the checkETag method has ifMatch and ifNoneMatch with quotes?

https://github.com/LearningLocker/learninglocker/blob/e094d71b589625d9b1daa50634a919f84c5c2322/app/locker/repository/Document/EloquentDocumentRepository.php#L323-L335

[ryasmi]

I really need to find a way to reproduce this issue. If you can find a way to reproduce it via Postman you would be an absolute hero!

[davidpesce]

OK, lemme get at it with Postman

On Wed, Feb 25, 2015 at 5:44 PM Ryan Smith notifications@github.com wrote:

I really need to find a way to reproduce this issue. If you can find a way to reproduce it via Postman https://chrome.google.com/webstore/detail/postman-rest-client/fdmmgilgnpjigdojojpjoooidkmcomcm?hl=en you would be an absolute hero!

— Reply to this email directly or view it on GitHub https://github.com/LearningLocker/learninglocker/issues/490#issuecomment-76077560 .

[fugu13]

I can take a quick look into this, though I'm not sure the exact current unexpected behavior (long thread!). Could someone summarize what's currently under investigation?

[ryasmi]

Thanks so much @davidpesce!

Thanks @fugu13. There is some case where pushing to the state API with an If-Match header fails the precondition even though the If-Match header appears to match the ETag. I hope that makes sense. Currently the issue is being reproduced by @davidpesce via @garemoko's Moodle plugin (I believe).

[fugu13]

@davidpesce I see you've provided the If-Match header being sent by your request, could you do a GET on what's stored in the location in question and provide the complete ETag header returned?

[fugu13]

Could you do a GET without specifying If-Match and provide that output?

[davidpesce]

Let me try that again...

Get Response

array(4) {
  ["contents"]=>
  bool(false)
  ["metadata"]=>
  NULL
  ["code"]=>
  array(13) {
    [0]=>
    string(32) "HTTP/1.0 412 Precondition Failed"
    [1]=>
    string(35) "Date: Wed, 25 Feb 2015 23:03:12 GMT"
    [2]=>
    string(39) "Server: Apache/2.4.6 (CentOS) PHP/5.6.4"
    [3]=>
    string(19) "Vary: Authorization"
    [4]=>
    string(23) "X-Powered-By: PHP/5.6.4"
    [5]=>
    string(39) "Cache-Control: private, must-revalidate"
    [6]=>
    string(16) "pragma: no-cache"
    [7]=>
    string(11) "expires: -1"
    [8]=>
    string(31) "X-Experience-API-Version: 1.0.1"
    [9]=>
    string(411) "Set-Cookie: laravel_session=eyJpdiI6Ijl2UlBRUGxMZW9majlcL0Zrc0NZSFwvbk1VYWlCXC9aUG5BbjQrS3lYQmJFTlU9IiwidmFsdWUiOiJZekl1NFRKd3d3YndURit0MXpsUTB5VWJhVldnalhXaVlrWlwvWld0TGZORjJ4UW1GbkVMMDVEMzJvSGNyUm9zMUphRW13dFE2ZklPTUhzWEVTREZ0elE9PSIsIm1hYyI6Ijk4MDRiMmNhZWRkZTFjMTAyOGY2MTI5OWYyYjBhYmM4ZDY5YWUyOGRiYjUyMDU5ZGJlMTA1OTgzMjgyMzUwNDQifQ%3D%3D; expires=Thu, 26-Feb-2015 01:03:12 GMT; Max-Age=7200; path=/; httponly"
    [10]=>
    string(20) "Content-Length: 3935"
    [11]=>
    string(17) "Connection: close"
    [12]=>
    string(30) "Content-Type: application/json"
  }
  ["EtagHeader"]=>
  string(53) "If-Match : "02A7F24DCC72C415DB410367EB8D82FF45573732""
}

Stream Options

array(2) {
  ["ssl"]=>
  array(1) {
    ["verify-peer"]=>
    bool(false)
  }
  ["http"]=>
  array(4) {
    ["method"]=>
    string(3) "PUT"
    ["ignore_errors"]=>
    bool(false)
    ["header"]=>
    array(5) {
      [0]=>
      string(129) "Authorization: Basic OGZjMDIyNmE2YTJhMWZlOTViOTBkNzVkODlkZTZhMzc2MTg3YjhlYTplZThjNjUxYTI2YzhjNjg5YjgyNzdhNWVjYTkzNTlhN2QxZjdjYTUw"
      [1]=>
      string(30) "Content-Type: application/json"
      [2]=>
      string(37) "Accept: application/json, */*; q=0.01"
      [3]=>
      string(31) "X-Experience-API-Version: 1.0.2"
      [4]=>
      string(53) "If-Match : "02A7F24DCC72C415DB410367EB8D82FF45573732""
    }
    ["content"]=>
    string(123) "{"6c3c14f1-844f-455b-a85b-96f4e940f2ef":{"created":"2015-02-25T16:31:00-05:00","lastlaunched":"2015-02-25T18:03:11-05:00"}}"
  }
}

Stream Params

array(3) {
  ["activityId"]=>
  string(52) "http://lrs.scrubbed.com/test1/story.html2"
  ["agent"]=>
  string(90) "{"name":"Admin User","mbox":"mailto:support@scrubbed.com","objectType":"Agent"}"
  ["stateId"]=>
  string(49) "http://tincanapi.co.uk/stateapikeys/registrations"
}

Request

http://lrs.scrubbed.com/data/xAPI/statements?activityId=http://lrs.scrubbed.com/test1/story.html2&agent={"name":"Admin User","mbox":"mailto:support@scrubbed.com","objectType":"Agent"}&stateId=http://tincanapi.co.uk/stateapikeys/registrations

[fugu13]

This looks like a PUT request. What I'm wondering is, if you make a GET request (without an if-match header in case the logic's there for that), what do you get back?

(On that note, one thing I'd recommend for LL generally is for responses to always include the current ETag, even if they're 4XX. It isn't required by HTTP, but it is allowed, and it helps a lot.)

[davidpesce]

Hmm, I'll try to figure out how to get the error output on GET. It's not causing an error so the debug output doesn't display.

I'm trying to get this to work within Postman, which "should" allow me to do a get request. Unfortunately I'm getting an invalid json error.

[fugu13]

Even if you're getting invalid JSON, you might be able to inspect the headers of the response (perhaps in the browser's console? not super familiar with Postman), which should be enough

[davidpesce]

GET to the statements endpoint returns 200 OK.

[fugu13]

nods what I'm interested in seeing is the full ETag header out of the response (it should be sent in the response... if not, that's another thing needed ;) )

[davidpesce]

GET to the statement endpoint returns the entire contents of db.statements (at least via postman it does).

Are you sure you want the GET for the statements endpoint? Or are you looking for something else?

[davidpesce]

Oddly, if I do the PUT without the IfMatch, I get (via postman):

{
"error": true,
"success": false,
"message": "A statement ID is required to PUT."
}

There is a stateID included in the request.

[fugu13]

Wait, statements? Oh!

I'm not quite sure why you're getting a 412 (that shouldn't be happening), but your PUT request doesn't make sense. Everything about it looks like a PUT to the State API, but you aren't using the State API endpoint. You're using http://lrs.scrubbed.com/data/xAPI/statements, but that should be http://lrs.scrubbed.com/data/xAPI/activities/state .

There's definitely a bug with the Statements API responding like that (it should be responding 400 either because the statementId parameter is missing or because there are extra parameters that aren't for that endpoint, either way), but there might not be a bug with the State API.

[davidpesce]

Sorry, that's a typo in my debug out. it is sending it to activities/state. I copied my debug from a prior line.

[davidpesce]

GET to activities/state returns:

{"error":true,"success":false,"message":"Required parameter is missing - activityId","trace":"#0 \/var\/www\/learninglocker\/app\/controllers\/xapi\/DocumentController.php(22): Controllers\\xAPI\\DocumentController->checkParams(Array, Array, Array)\n#1 \/var\/www\/learninglocker\/app\/controllers\/xapi\/DocumentController.php(52): Controllers\\xAPI\\DocumentController->getIndexData(Array)\n#2 \/var\/www\/learninglocker\/app\/controllers\/xapi\/BaseController.php(53): Controllers\\xAPI\\DocumentController->index()\n#3 \/var\/www\/learninglocker\/app\/controllers\/xapi\/BaseController.php(36): Controllers\\xAPI\\BaseController->get()\n#4 [internal function]: Controllers\\xAPI\\BaseController->selectMethod()\n#5 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/Controller.php(231): call_user_func_array(Array, Array)\n#6 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/ControllerDispatcher.php(93): Illuminate\\Routing\\Controller->callAction('selectMethod', Array)\n#7 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/ControllerDispatcher.php(62): Illuminate\\Routing\\ControllerDispatcher->call(Object(Controllers\\xAPI\\StateController), Object(Illuminate\\Routing\\Route), 'selectMethod')\n#8 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/Router.php(962): Illuminate\\Routing\\ControllerDispatcher->dispatch(Object(Illuminate\\Routing\\Route), Object(Illuminate\\Http\\Request), 'Controllers\\\\xAP...', 'selectMethod')\n#9 [internal function]: Illuminate\\Routing\\Router->Illuminate\\Routing\\{closure}()\n#10 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/Route.php(109): call_user_func_array(Object(Closure), Array)\n#11 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/Router.php(1028): Illuminate\\Routing\\Route->run(Object(Illuminate\\Http\\Request))\n#12 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Routing\/Router.php(996): Illuminate\\Routing\\Router->dispatchToRoute(Object(Illuminate\\Http\\Request))\n#13 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Foundation\/Application.php(776): Illuminate\\Routing\\Router->dispatch(Object(Illuminate\\Http\\Request))\n#14 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Foundation\/Application.php(746): Illuminate\\Foundation\\Application->dispatch(Object(Illuminate\\Http\\Request))\n#15 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Session\/Middleware.php(72): Illuminate\\Foundation\\Application->handle(Object(Illuminate\\Http\\Request), 1, true)\n#16 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Cookie\/Queue.php(47): Illuminate\\Session\\Middleware->handle(Object(Illuminate\\Http\\Request), 1, true)\n#17 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Cookie\/Guard.php(51): Illuminate\\Cookie\\Queue->handle(Object(Illuminate\\Http\\Request), 1, true)\n#18 \/var\/www\/learninglocker\/vendor\/stack\/builder\/src\/Stack\/StackedHttpKernel.php(23): Illuminate\\Cookie\\Guard->handle(Object(Illuminate\\Http\\Request), 1, true)\n#19 \/var\/www\/learninglocker\/vendor\/laravel\/framework\/src\/Illuminate\/Foundation\/Application.php(642): Stack\\StackedHttpKernel->handle(Object(Illuminate\\Http\\Request))\n#20 \/var\/www\/learninglocker\/public\/index.php(49): Illuminate\\Foundation\\Application->run()\n#21 {main}"}

[fugu13]

Could you double check that? The response you saw here:

Oddly, if I do the PUT without the IfMatch, I get (via postman):

{ "error": true, "success": false, "message": "A statement ID is required to PUT." }

There is a stateID included in the request.

Strongly suggests your requests are going to /statements not /activities/state

[fugu13]

Re: the GET to activities/state, don't forget to include all the URL parameters you used for your PUT

[davidpesce]

Let me try something different.

[fugu13]

Hmm, there might just be a different way to do it, since its definitely legal

[davidpesce]

It was a different tab. Header is 200 OK

Response is:

{"6c3c14f1-844f-455b-a85b-96f4e940f2ef":{"created":"2015-02-25T16:31:00-05:00","lastlaunched":"2015-02-25T18:03:11-05:00"}}

[fugu13]

Could you find the response headers, particularly the ETag header? Looking at the Postman docs it looks like there should be a tab for headers next to the tab for body

[davidpesce]

Ahhhhh, there it is:

Accept-Ranges → bytes
Cache-Control → public
Connection → Keep-Alive
Content-Disposition → attachment; filename="1424907021_879"
Content-Length → 123
Content-Type → application/x-www-form-urlencoded
Date → Wed, 25 Feb 2015 23:49:21 GMT
ETag → "706ECF913A3267400E3ED8D137FA874184E5A9E9"
Keep-Alive → timeout=5, max=100
Last-Modified → Wed, 25 Feb 2015 23:30:21 GMT
Server → Apache/2.4.6 (CentOS) PHP/5.6.4
Updated → 2015-02-25T23:30:21+0000
Vary → Authorization
X-Experience-API-Version → 1.0.1
X-Powered-By → PHP/5.6.4

[fugu13]

If this is telling the truth, then 412 Precondition Failed is the right response (at least, considered narrowly). There's a different ETag for the resource than there is in the PUT request. Where are you getting the ETag in the PUT request from?

[davidpesce]

Well, with my other testing, it's updated the Etag. It's the correct etag for what's in the db.documentapi. As well as what's displayed in the updated debug output.

Let me switch back to the Golf Example and see what happens.

[fugu13]

After you've tried what you're planning, I'd be interested in seeing the headers from a successful GET followed by the PUT output with precondition failed like you've had before (with no updates in between). Sorry for the slow plodding nature of this debugging approach, but I've found careful elimination of possibilities is often the approach that works best for me.

[davidpesce]

OK, I think LL is in the clear on this one. Here's what I did.

1. Deleted LL db and created a new instance (with conformance branch)
2. Added the quote trimming to the moodle plugin
3. Launched the golf TC example (works and is tracked)
4. Went back to launch golf TC example again and IT WORKS!

It looks like my issue was partially with the double quotes (within moodle plugin) and with the Storyline content I was using.

[fugu13]

Glad to hear it! Working is good :)

From the conversation, I recommend someone make sure that if-match on statement PUT with State-related parameters doesn't cause precondition failed, and that LL add ETag to the headers sent back on all failures in the document APIs.

[davidpesce]

@ryansmith94 @garemoko Confirming this is an issue with the extra quotes. I was able to test the plugin fix (removing the extra quotes) on scormcloud and it works.

That being said, should LL check and strip quotes on incoming ETags? It appears that scormcloud does so. This may be better to start an offline discussion or a new issue. I'll leave it up to you.

[fugu13]

I'm not sure what you mean by "check and strip quotes". The ETag and If-Match and so forth parts of the HTTP specifications are unambiguous; ETag values in the headers must be in quotes. It doesn't really matter how they behave behind the scenes to check/store ETags, its purely a question of communication.

What's the specific SCORMCloud behavior you're seeing? If they're violating the HTTP specs, they need to change their code.

[davidpesce]

My guess is that there's some error correction on scormcloud's side that strips out extraneous quotes (or other chars) on incoming requests. And that's why there hasn't been an issue with the plugin using scormcloud. Removing the extra quotes from the plugin does not break compatibility with scormcloud, but wanted to bring up the option to do some error correction on the LL side that may catch issues like this in the future and fail gracefully.

[fugu13]

Yeah, if they're doing that it is definitely wrong, and once verified someone should file a bug.

Sent from my iPhone

On Feb 25, 2015, at 6:09 PM, davidpesce notifications@github.com wrote:

My guess is that there's some error correction on scormcloud's side that strips out extraneous quotes (or other chars) on incoming requests. And that's why there hasn't been an issue with the plugin using scormcloud. Removing the extra quotes from the plugin does not break compatibility with scormcloud, but wanted to bring up the option to do some error correction on the LL side that may catch issues like this in the future and fail gracefully.

— Reply to this email directly or view it on GitHub.

[fugu13]

That is, learning locker rejecting the doubled quotes is correct (and vastly preferable).

Sent from my iPhone

On Feb 25, 2015, at 6:09 PM, davidpesce notifications@github.com wrote:

My guess is that there's some error correction on scormcloud's side that strips out extraneous quotes (or other chars) on incoming requests. And that's why there hasn't been an issue with the plugin using scormcloud. Removing the extra quotes from the plugin does not break compatibility with scormcloud, but wanted to bring up the option to do some error correction on the LL side that may catch issues like this in the future and fail gracefully.

— Reply to this email directly or view it on GitHub.

[davidpesce]

Sounds good!

@ryansmith94 This one is tested and confirmed working!

[garemoko]

Just catching up on this thread. I notice that in the headers from Learning Locker the ETag is in quotes:

ETag → "706ECF913A3267400E3ED8D137FA874184E5A9E9"

Just wondering if SCORM Cloud includes those quotes or not. E.g.

ETag → 706ECF913A3267400E3ED8D137FA874184E5A9E9

Could explain why the trim code works on both LRS - they don't exist on Cloud. I'd be surprised if SCORM is trimming double quotes; seems like something that'd be difficult to accidentally do.

[scara]

Hi Andrew, RFC 2616 tells that the ETag header value must have quotes (quoted-string), http://tools.ietf.org/html/rfc2616#section-3.11. Each consumer should use the ETag raw value trimmed by the quotes while quotes must be added when preparing the HTTP response headers.

HTH, Matteo

[garemoko]

@scara - yeh I just reached that same conclusion. Interested to know if Cloud is doing that wrong though.

That said, having read this again I'm even less sure this is the issue. Looking up at the thread I see:

"If-Match : "02A7F24DCC72C415DB410367EB8D82FF45573732"" as the header. PHP puts all the headers in quotes when outputting as a var_dump so the actual header would be If-Match : "02A7F24DCC72C415DB410367EB8D82FF45573732", which is correct and Learning Locker is wrong to reject.

Looking at @davidpesce's PR to the Moodle plugin, it seems like that code would be sending If-Match : 02A7F24DCC72C415DB410367EB8D82FF45573732, which is wrong and should be rejected by both LRS, rather than accepted by both as @davidpesce reports.

@davidpesce are you able to confirm or deny? :-)