onConnect does not get called

MarcVanDaele90 commented 2 years ago

Describe the bug I assume that, after a succesfull login, that onConnect would get called, right? In there I should redirect to my actual app, right? This does not seem to happen. I have the folowing setup

a firebase cloud function using ltijs and ltijs-firestore, configured as follows

const functions = require("firebase-functions");
const {default: Firestore} = require("@examind/ltijs-firestore");
const debug = require("debug");
debug.enable("provider:*");

const lti = require("ltijs").Provider;

lti.setup("LTIKEY", // Key used to sign cookies and tokens
    {
      plugin: new Firestore(),
    },
    {
      appRoute: "/app", loginRoute: "/login",
      cookies: {
        secure: true,
        sameSite: "None",
      },
      devMode: true,
    },
);

// Set lti launch callback
lti.onConnect((token, req, res) => {
  functions.logger.log("onConnect");
  functions.logger.log(token);
  return res.redirect("https://app.wijsr.com/");
  // return res.send('It\'s alive!')
});

const setup = async () => {
  await lti.deploy({port: 3000}); // Specifying port. Defaults to 3000

  await lti.registerPlatform({
    url: "https://sandbox.moodledemo.net",
    name: "Platform Name",
    clientId: "zVGH8dJaW6qAZqy",
    authenticationEndpoint: "https://sandbox.moodledemo.net/mod/lti/auth.php",
    accesstokenEndpoint: "https://sandbox.moodledemo.net/mod/lti/token.php",
    authConfig: {method: "JWK_SET", key: "https://sandbox.moodledemo.net/mod/lti/certs.php"},
  });
};

setup();
exports.ltijs = functions.region("europe-west1").https.onRequest(lti.app);

As LMS, I use https://demo.moodle.net/ where I've added an external tool that links to the LTI firebase wrapper. The configuration is done as shown below This results in the following platform urls (this clientId and urls are used in the platform registration above)

Screenshot from 2022-07-31 19-22-45

I've added this external tool to a Moodle course and started the course.

This resulted in the following firebase/ltijs logging

Function execution started
2022-07-31T17:11:25.725Z provider:main Receiving request at path: /login
2022-07-31T17:11:25.726Z provider:main Receiving a login request from: https://sandbox.moodledemo.net, clientId: zVGH8dJaW6qAZqy
2022-07-31T17:11:25.881Z provider:main Redirecting to platform authentication endpoint
2022-07-31T17:11:25.881Z provider:main Target Link URI:  https://europe-west1-wijsrlti.cloudfunctions.net/ltijs/app
2022-07-31T17:11:25.882Z provider:main Login request: 
2022-07-31T17:11:25.882Z provider:main {
  response_type: 'id_token',
  response_mode: 'form_post',
  id_token_signed_response_alg: 'RS256',
  scope: 'openid',
  client_id: 'zVGH8dJaW6qAZqy',
  redirect_uri: 'https://europe-west1-wijsrlti.cloudfunctions.net/ltijs/app',
  login_hint: '2',
  nonce: 'keeszy8cmzfwmoc12pgr7wf97',
  prompt: 'none',
  state: '6b4c63e575fe97d7835655e4718b463da39d9e72b472e3bdd7',
  lti_message_hint: '4',
  lti_deployment_id: '1'
}
Function execution took 167 ms. Finished with status code: 302
Function execution started
2022-07-31T17:11:26.417Z provider:main Receiving request at path: /app
2022-07-31T17:11:26.417Z provider:main Path does not match reserved endpoints
2022-07-31T17:11:26.417Z provider:main Cookies received: 
2022-07-31T17:11:26.417Z provider:main [Object: null prototype] {
  'ltiaHR0cHM6Ly9zYW5kYm94Lm1vb2RsZWRlbW8ubmV0elZHSDhkSmFXNnFBWnF5MQ%3D%3D': '2',
  state6b4c63e575fe97d7835655e4718b463da39d9e72b472e3bdd7: 'https://sandbox.moodledemo.net'
}
2022-07-31T17:11:26.417Z provider:main Received idtoken for validation
2022-07-31T17:11:26.417Z provider:auth Response state: 6b4c63e575fe97d7835655e4718b463da39d9e72b472e3bdd7
2022-07-31T17:11:26.418Z provider:auth Attempting to validate iss claim
2022-07-31T17:11:26.418Z provider:auth Request Iss claim: https://sandbox.moodledemo.net
2022-07-31T17:11:26.418Z provider:auth Response Iss claim: https://sandbox.moodledemo.net
2022-07-31T17:11:26.418Z provider:auth Attempting to retrieve registered platform
2022-07-31T17:11:26.534Z provider:auth Retrieving key from jwk_set
2022-07-31T17:11:26.671Z provider:auth Converting JWK key to PEM key
2022-07-31T17:11:26.672Z provider:auth Attempting to verify JWT with the given key
2022-07-31T17:11:26.674Z provider:auth Token signature verified
2022-07-31T17:11:26.674Z provider:auth Initiating OIDC aditional validation steps
2022-07-31T17:11:26.674Z provider:auth Validating if aud (Audience) claim matches the value of the tool's clientId given by the platform
2022-07-31T17:11:26.674Z provider:auth Aud claim: zVGH8dJaW6qAZqy
2022-07-31T17:11:26.674Z provider:auth Checking alg claim. Alg: RS256
2022-07-31T17:11:26.674Z provider:auth Max age parameter:  10
2022-07-31T17:11:26.674Z provider:auth Checking iat claim to prevent old tokens from being passed.
2022-07-31T17:11:26.674Z provider:auth Iat claim: 1659287485
2022-07-31T17:11:26.674Z provider:auth Exp claim: 1659287545
2022-07-31T17:11:26.674Z provider:auth Current_time: 1659287486.674
2022-07-31T17:11:26.674Z provider:auth Time passed: 1.6740000247955322
2022-07-31T17:11:26.674Z provider:auth Validating nonce
2022-07-31T17:11:26.674Z provider:auth Nonce: keeszy8cmzfwmoc12pgr7wf97
2022-07-31T17:11:26.675Z provider:auth Tool's clientId: zVGH8dJaW6qAZqy
2022-07-31T17:11:26.726Z provider:auth Storing nonce
2022-07-31T17:11:26.800Z provider:auth Initiating LTI 1.3 core claims validation
2022-07-31T17:11:26.800Z provider:auth Checking Message type claim
2022-07-31T17:11:26.800Z provider:auth Checking Target Link Uri claim
2022-07-31T17:11:26.800Z provider:auth Checking Resource Link Id claim
2022-07-31T17:11:26.800Z provider:auth Checking LTI Version claim
2022-07-31T17:11:26.800Z provider:auth Checking Deployment Id claim
2022-07-31T17:11:26.800Z provider:auth Checking Sub claim
2022-07-31T17:11:26.800Z provider:auth Checking Roles claim
2022-07-31T17:11:26.852Z provider:auth Successfully validated token!
2022-07-31T17:11:27.149Z provider:main Generating ltik
2022-07-31T17:11:27.150Z provider:main Redirecting to endpoint with ltik
Function execution took 741 ms. Finished with status code: 302

At first sight, the logging seems to be OK (except maybe the "Path does not match reserved endpoints"?) but I would expect to see a logline for 'onConnect' at the end and a redirect to This does not seem to happen and Moodle just shows the following

Any suggestions on what I could try?

Ltijs version "@examind/ltijs-firestore": "^0.1.7", "firebase-admin": "^10.0.2", "firebase-functions": "^3.18.0", "ltijs": "^5.8.9"

NodeJS version

16

Platform used

Moodle

johnnyoshika commented 2 years ago

Inside lti.onConnect, try return lti.redirect(res, "https://app.wijsr.com/"); instead of return res.redirect("https://app.wijsr.com/");

MarcVanDaele90 commented 2 years ago

Thanks for the suggestion. Unfortunately, I get the same result (and same logging). Based on my logging (the missing "onConnect" logline), I think onConnect is not called (which could explain why your suggested change has no effect).

Maybe I misunderstand when the onConnect is called exactly and where I should launch my actual tool?

johnnyoshika commented 2 years ago

I think I found the problem. Inspecting your logs and comparing them to mine, here's what I see:

Yours:

2022-07-31T17:11:26.852Z provider:auth Successfully validated token!
2022-07-31T17:11:27.149Z provider:main Generating ltik
2022-07-31T17:11:27.150Z provider:main Redirecting to endpoint with ltik
Function execution took 741 ms. Finished with status code: 302

Mine:

2022-08-01T16:15:19.301Z provider:auth Successfully validated token!
2022-08-01T16:15:20.358Z provider:main Generating ltik
2022-08-01T16:15:20.359Z provider:main Forwarding request to next handler

After Forwarding request to next handler, my lti.onConnect() handler is called.

Looking at ltijs' codebase here, it looks lti.onConnect() is called because I have ltiaas set to true:

lti.setup("LTIKEY", 
    {
      plugin: new Firestore(),
    },
    {
         ltiaas: true,
         // other settings
    },
);

Yours is missing the ltiaas setting.

johnnyoshika commented 2 years ago

I did a little bit more testing. When I don't specify ltiaas: true, I get the Redirecting to endpoint with ltik log just like you do, but it still calls my lti.onConnect() callback. Are you sure your lti.onConnect() is not being called?

MarcVanDaele90 commented 2 years ago

When adding ltiaas:true the redirect to my app works indeed! Thanks for having this detailed look. That's appreciated a lot!

I can confirm that in this case I do see the onConnect logline. However, I don't see it without this ltiaas:true

I'm still a bit confused by the "Path does not match reserved endpoints" logline. Is this expected behavior or should I fix something there?

johnnyoshika commented 2 years ago

Glad to see that it's working now.

Regarding Path does not match reserved endpoints, the logic is here:

https://github.com/Cvmcosta/ltijs/blob/master/src/Provider/Provider.js#L211-L214

You can see in the comments when it gets logged.

MarcVanDaele90 commented 2 years ago

Thanks for your assistance! Feel free to close the issue. And thanks for clarifying Path does not match reserved endpoints. When reading this, it sounds like something was configured incorrectly while it seems to be expected behavior, right?

Maybe (minor suggestion), it might be useful to rephrase this logline?

johnnyoshika commented 2 years ago

@Cvmcosta please close this issue

Cvmcosta commented 2 years ago

Thank you so much @johnnyoshika For assisting in this issue. I will consider rephrasing the Path does not match reserved endpoints sentence.

Cvmcosta / ltijs

onConnect does not get called #157