Token expiration issue

[onebonsai]

Hi,

we have had a conversation about the issue to connect to Moodle. After much digging, we might have found a potential cause of the problem.

The root of the problem seems to be that sometimes the token communicated back from Moodle has not exactly the same time stamp as the current time at the server of the tool. This results in an error when sending back the score to Moodle.

This is a very subtle issue, as it does not always happen (however it does often happen) and will also depend on where the two servers are located. If the platform and tool are on the same server, the issue does not occur. If they are in the same datacenter, it does not occur most of the times. If they are in the same country, it might occur. If they are on the other side of the planet, often it occurs.

    public function hasScope(string $scope = ''): bool
    {
        if (str_ends_with($scope, '.readonly')) {
            $scope2 = substr($scope, 0, -9);
        } else {
            $scope2 = $scope;
        }
        return !empty($this->token) && (empty($this->expires) || ($this->expires > time())) &&
            (empty($scope) || empty($this->scopes) || (in_array($scope, $this->scopes) || in_array($scope2, $this->scopes)));
    }

This is the function in AccessToken.php that is causing the issue. If $this->expires <= time() it returns an error. So if the times differ even with 1 second, it will fail.

This is a detailed log, showing the problem:

[2024-12-02 08:34:55] production.INFO: hasScope 2  
[2024-12-02 08:34:55] production.INFO: Token expires: 1733128494 - 1733128495  
[2024-12-02 08:34:55] production.INFO: Token expired!!!  
[2024-12-02 08:34:55] production.INFO: HTTP OUT: {"ok":false,"request":null,"requestHeaders":[],"response":null,"responseHeaders":[],"responseJson":null,"relativeLinks":[],"status":0,"error":"Unable to obtain an access token for scope: https:\/\/purl.imsglobal.org\/spec\/lti-ags\/scope\/score"}  
[2024-12-02 08:34:55] production.INFO: Score Service: {"unsigned":false}  
[2024-12-02 08:34:55] production.INFO: HTTP Response:   
[2024-12-02 08:34:55] production.INFO: HTTP: {"ok":false,"request":null,"requestHeaders":[],"response":null,"responseHeaders":[],"responseJson":null,"relativeLinks":[],"status":0,"error":"Unable to obtain an access token for scope: https:\/\/purl.imsglobal.org\/spec\/lti-ags\/scope\/score"}  
[2024-12-02 08:34:55] production.INFO: Token expires: 1733128494 - 1733128495  
[2024-12-02 08:34:55] production.INFO: Token expired!!!  
[2024-12-02 08:34:55] production.INFO: Scopes Requested  
[2024-12-02 08:34:55] production.INFO: HTTP TEST  
[2024-12-02 08:34:56] production.INFO: Http\HttpMessage->send POST request to 'https://augmentedreality.eskilledlms.com.au/mod/lti/token.php'
POST /mod/lti/token.php HTTP/2
Host: augmentedreality.eskilledlms.com.au
accept: application/json
content-type: application/x-www-form-urlencoded; charset=UTF-8
content-length: 0
Response:
HTTP/2 400 
date: Mon, 02 Dec 2024 08:34:55 GMT
content-type: text/html; charset=utf-8
server: Apache/2.4.62 (CentOS Stream) OpenSSL/3.2.2
x-powered-by: PHP/8.3.14

{
  "error" : "invalid_request"
}  

I added a lot of extra logging to show. The line "Token expires" shows the small difference (1 second). This is between a server in Frankfurt and Sydney.

The function is called through

$scoreService = new Service\Score($this->getPlatform(), $url);
            $scoreService->submit($ltiOutcome, $userResult);

I think to solve this issue, the code should account for small deviations, such as 1-5 seconds. Or maybe you have a better way to solve this?

[onebonsai]

When I adjust the code to accommodate with a 5 sec difference in token, things go further, but do not yet work fully.

I get this as result:

[2024-12-02 09:11:07] production.INFO: Token expires: 1733130666 - 1733130667  
[2024-12-02 09:11:07] production.INFO: Token expired!!!  
[2024-12-02 09:11:07] production.INFO: token: "96adb4bc739e0e"  
[2024-12-02 09:11:07] production.INFO: Expires: 1733130666  
[2024-12-02 09:11:07] production.INFO: Expired: no  
[2024-12-02 09:11:07] production.INFO: Expired delta: 1  
[2024-12-02 09:11:07] production.INFO: Scope empty: ""  
[2024-12-02 09:11:07] production.INFO: Scopes empty: ["https:\/\/purl.imsglobal.org\/spec\/lti-ags\/scope\/score"]  
[2024-12-02 09:11:07] production.INFO: In scopes: no  
[2024-12-02 09:11:07] production.INFO: In scopes2: no  
[2024-12-02 09:11:07] production.INFO: Result: true  
[2024-12-02 09:11:08] production.INFO: Http\HttpMessage->send POST request to 'https://domain.com/mod/lti/service.php'
POST /mod/lti/service.php HTTP/2
Host: augmentedreality.eskilledlms.com.au
authorization: Bearer 96adb41e39e0e
content-type: application/xml; charset=UTF-8
content-length: 999
accept: application/xml

<?xml version = "1.0" encoding = "UTF-8"?>
<imsx_POXEnvelopeRequest xmlns = "http://www.imsglobal.org/services/ltiv1p1/xsd/imsoms_v1p0">
  <imsx_POXHeader>
    <imsx_POXRequestHeaderInfo>
      <imsx_version>V1.0</imsx_version>
      <imsx_messageIdentifier>674d79aabdfea</imsx_messageIdentifier>
    </imsx_POXRequestHeaderInfo>
  </imsx_POXHeader>
  <imsx_POXBody>
    <replaceResultRequest>
      <resultRecord>
        <sourcedGUID>
          <sourcedId>{&quot;data&quot;:{&quot;instanceid&quot;:&quot;4&quot;,&quot;userid&quot;:&quot;30&quot;,&quot;typeid&quot;:&quot;7&quot;,&quot;launchid&quot;:538115073},&quot;hash&quot;:&quot;f090f185b0dae44724a1075edc&quot;}</sourcedId>
        </sourcedGUID>
        <result>
          <resultScore>
            <language>en-US</language>
            <textString>0</textString>
          </resultScore>
        </result>
      </resultRecord>
    </replaceResultRequest>
  </imsx_POXBody>
</imsx_POXEnvelopeRequest>
Response:
HTTP/2 200 
date: Mon, 02 Dec 2024 09:11:08 GMT
content-type: text/html; charset=utf-8
server: Apache/2.4.62 (CentOS Stream) OpenSSL/3.2.2
x-powered-by: PHP/8.3.14
vary: Accept-Encoding

<?xml version="1.0" encoding="UTF-8"?>
<imsx_POXEnvelopeResponse xmlns="http://www.imsglobal.org/services/ltiv1p1/xsd/imsoms_v1p0"><imsx_POXHeader><imsx_POXResponseHeaderInfo><imsx_version>V1.0</imsx_version><imsx_messageIdentifier>1793614090</imsx_messageIdentifier><imsx_statusInfo><imsx_codeMajor>failure</imsx_codeMajor><imsx_severity>status</imsx_severity><imsx_description>Missing or invalid consumer key or access token.
* line 56 of /mod/lti/service.php: Exception thrown
</imsx_description><imsx_messageRefIdentifier/><imsx_operationRefIdentifier>unknownRequest</imsx_operationRefIdentifier></imsx_statusInfo></imsx_POXResponseHeaderInfo></imsx_POXHeader><imsx_POXBody><unknownResponse/></imsx_POXBody></imsx_POXEnvelopeResponse>

This might again be a Moodle issue. In this case, the token is still used even if the time is slightly off. This might also be a violation of the LTI1.3 standard... Maybe this gives you an idea?

[spvickers]

This does indeed sound like a Moodle issue, or perhaps just an error with the clock on either the Moodle or tool server. Your logs show that you are still getting the "Unable to obtain an access token for scope: https://purl.imsglobal.org/spec/lti-ags/scope/score" (as per issue #93), so it might also be just a tool configuration error in Moodle. If you are finding that the error is just a few seconds, then my suspicion is that the clock on one of the servers has not been correctly adjusted when daylight savings time ended/started. Tokens are issued for an hour and so a few seconds difference in clock times should not be a problem.

[spvickers]

Your logs show the sending of a token with a value of "96adb41e39e0e"; are you able to share a copy of a request and response showing a token being issued by Moodle? In addition, your comments suggest that you are trying to use the Score service, but your logs show a request to the Basic Outcomes service; if this is the service you are wanting to use then you should be requesting the scope associated with this service when requesting an access token.