WeBWorK Problems

First student login with 2.19 sometimes fails to create an account?

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -
Number of replies: 18
You will want $CookieSecure = 1;. There is really no case where that should be 0 anymore. We need to change the default for that.

There are no real changes to LTI 1.1 authentication from WeBWorK 2.18 to 2.19. Content item selection was added, but that doesn't change the way that authentication works. So there is probably something in the configuration of the 2.19 server that is not set up right.

You noted that you have $authen{user_module} set in both authen_LTI.conf and in localOverrides.conf. It sounds like you want the one in localOverrides.conf to be in effect. That means that the one in localOverrides needs to be after the authen_LTI.conf file is included in localOverrides.conf. So make sure that is how it is set up.

Another thing to try is to enable the debugging facilities.  There are two of them that apply in this case.  The first is $debug_lti_parameters in authen_LTI.conf.  The second is much more general and comprehensive.  That is to set

debug:
  enabled: 1
in the webwork2.mojolicous.yml file.  If you do that you will also want to set the "logfile" option below that or you won't see the debugging messages anywhere when running webwork2 with hypnotoad.
In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
Thanks Glenn,

=========== summary ============
User id is |jpeismeier| (obtained from lis_person_contact_email_primary which was preferred_source_of_username)
User mail address is |jpeismeier@wpi.edu|
strip_domain_from_email is |1|
Student id is |jpeismeier|
preferred_source_of_username is |lis_person_contact_email_primary|
fallback_source_of_username is |lis_person_sourcedid|
preferred_source_of_student_id is |custom_canvas_user_login_id|

is the summary of setting debug_lti_parameters to 1 which seems okay for my simple test. The debug set in webwork2.mojolicous.yml was already there? It will take a while comparing students that were blocked vs students that LTI created accounts for.

When comparing 2.18 to 2.19 I did find this last weekend the lms url had a typo in both instances. Repairing 2.19 didn't alter the intermittent account creation concern that I see.
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -

If you mean the $LTI{v1p1}{LMS_url}, that won't matter.  That isn't used for authentication.  That is only used to display links in WeBWorK to the LMS when authentication fails or on logout.

If you have debug in webwork2.mojolicious.yml set, then try to compare the output in the debug.log file between a user for which LTI authentication works correctly and a user for which is fails, and report differences here.  It can be a bit challenging to sort out, because there is a lot of output generated.  You might want to watch that log file for size too.  It can become quite large rather quickly when debug is enabled on a production server.

In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
here is a failed student from the debug.log:

[Tue Jan 21 10:08:56.938671 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:08:56.938932 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced has been called for data verification
[Tue Jan 21 10:08:56.939099 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data
[Tue Jan 21 10:08:56.939325 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:08:56.939439 2025] WeBWorK::Authen::do_verify: db ok
[Tue Jan 21 10:08:56.939533 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::LDAP=HASH(0x5a32f3ddda88)
[Tue Jan 21 10:08:56.940135 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Tue Jan 21 10:08:56.940280 2025] WeBWorK::Authen::get_credentials: credential source: "params", user: "ntferony" key: "###UNDEF###"
[Tue Jan 21 10:08:56.940385 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Jan 21 10:08:56.942099 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN FAILED user unknown user_id=ntferony login_type=normal credential_source=params host=130.\
215.210.156 port=48684 UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36'.
[Tue Jan 21 10:08:56.942676 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Jan 21 10:08:56.942783 2025] WeBWorK::Authen::verify: result 0
[Tue Jan 21 10:08:56.952111 2025] WeBWorK::Authen::store_session: Deleting database session.
[Tue Jan 21 10:08:56.952799 2025] WeBWorK::Authen::store_session: The cookie session is expired.
[Tue Jan 21 10:10:01.171146 2025] WeBWorK::Authen::verify: BEGIN VERIFY

Does this help explain our issue? This is a course where most students have homework access with LTI creating their account first login.

This student appears to have success from the same course.

[Tue Jan 21 10:11:29.782376 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:11:29.782586 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced has been called for data verification
[Tue Jan 21 10:11:29.782698 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data
[Tue Jan 21 10:11:29.782909 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:11:29.783018 2025] WeBWorK::Authen::do_verify: db ok
[Tue Jan 21 10:11:29.783107 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::LDAP=HASH(0x5a32f6395af0)
[Tue Jan 21 10:11:29.783616 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="sbodkin", key="Iklk8hyPTF9NYaZkgKGE1u9Zotv36Fr7", timestamp="1737472215"
[Tue Jan 21 10:11:29.783742 2025] WeBWorK::Authen::get_credentials: credential source: "cookie", user: "sbodkin", key: "Iklk8hyPTF9NYaZkgKGE1u9Zotv36Fr7", timestamp: "1737472215"
[Tue Jan 21 10:11:29.783826 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Jan 21 10:11:29.785263 2025] WeBWorK::Authen::do_verify: check user ok
[Tue Jan 21 10:11:29.786168 2025] WeBWorK::Authen::verify_normal_user: sessionExists='1' keyMatches='1' timestampValid='1'
[Tue Jan 21 10:11:29.786408 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="sbodkin", key="Iklk8hyPTF9NYaZkgKGE1u9Zotv36Fr7", timestamp="1737472215"
[Tue Jan 21 10:11:29.786515 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='1' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Tue Jan 21 10:11:29.786694 2025] WeBWorK::Authen::set_params: params user='sbodkin' key='Iklk8hyPTF9NYaZkgKGE1u9Zotv36Fr7'
[Tue Jan 21 10:11:29.786804 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Jan 21 10:11:29.786920 2025] WeBWorK::Authen::verify: result 1
[Tue Jan 21 10:11:29.836045 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:11:29.836384 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced has been called for data verification
[Tue Jan 21 10:11:29.836547 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data
[Tue Jan 21 10:11:29.836810 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Jan 21 10:11:29.836993 2025] WeBWorK::Authen::do_verify: db ok


In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -

In neither of those cases is LTI authentication being used.  In both cases it starts with

WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data

That means that in both cases it is moving on to the LDAP authentication module and authentication occurs with that module.

In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by Alex Jordan -

"LTIAdvanced returning that it has insufficent data" is returned if one of oauth_consumer_key, oauth_signature, oauth_nonce, or oauth_timestamp is not defined in the params for the LTI request. If you edit line 112 of lib/WeBWorK/Authen/LTIAdvanced.pm, you could have the log also print the values of these params to track down which one(s) are missing, to narrow the issue down.

I missed which LMS you are using, but in D2L, when I am an instructor, I can visit the External Learning Tools manager and click to view the link request, where I can see the params it would send. Maybe other LMSs let you do something similar. Of course, this may not help if it is sending them for you but not for one of your students.

In reply to Alex Jordan

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
I am using canvas. With LTI debug turned on this morning I do see:

oauth_nonce => sM4aluonWpqDLfUeD4tA4UcdO7X5CkKB0RgXPIY2Y
oauth_signature => fLy6aiBZfbIMBt8pF72WwsIQa/w=
oauth_consumer_key => Webwork
oauth_timestamp => 1737628800

so is there issues LMS side sending oath some times or configuration webwork side that I missed or didn't define correctly? I will try to print from the perl module using the debug call to print ?
In reply to Alex Jordan

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
unless I printed incorrectly I see:

[Thu Jan 23 16:02:14.189672 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data
[Thu Jan 23 16:02:14.189952 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: oauth_consumer_key
[Thu Jan 23 16:02:14.190128 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: oauth_signature
[Thu Jan 23 16:02:14.190301 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: oauth_noncew
[Thu Jan 23 16:02:14.190450 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: oauth_timestamp

with debug prints

debug("oauth_consumer_key" . $c->param("oauth_consumer_key"));
debug("oauth_signature" . $c->param("oauth_signature"));
debug("oauth_noncew" . $c->param("oauth_noncew"));
debug("oauth_timestamp" . $c->param("oauth_timestamp"));
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Danny Glin -
Other than the extra w at the end of "nonce" that looks like it should work.

From what you've posted so far there still isn't an instance showing that a student successfully logged in via LTI. In the course login log look for entries that include "credential_source=LTIAdvanced". If you can find an entry with a user_id that belongs to a student then we can try to determine what's different about that student.
In reply to Danny Glin

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
Does the log below suggest that LTI did work?

[Fri Jan 24 01:48:06.289953 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN OK user_id=cwvolkert login_type=normal credential_source=LTIAdvanced host=130.215.217.96 port=47424 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36'.
[Fri Jan 24 03:23:35.399664 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN OK user_id=crcermak login_type=normal credential_source=LTIAdvanced host=130.215.15.240 port=57914 UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36'.

If yes, I still am very confused on LTI configs.

cat authen_LTI.conf|grep -v "^#"|grep "\S"
$debug_lti_parameters = 0;
$debug_lti_grade_passback = 0;
$authen{user_module} = [
# { '*' => 'WeBWorK::Authen::LTIAdvantage' }, # first try LTI 1.3
{ '*' => 'WeBWorK::Authen::LTIAdvanced' }, # next try LTI 1.1
{ '*' => 'WeBWorK::Authen::Basic_TheLastOption' } # fallback authorization method
];
$authen{admin_module} = [
#'WeBWorK::Authen::LTIAdvantage',
#'WeBWorK::Authen::LTIAdvanced',
'WeBWorK::Authen::Basic_TheLastOption'
];
include('conf/authen_LTI_1_1.conf');
$LTIVersion = 'v1p1';
$LTIAccountCreationCutoff = 'ta';
$LMSManageUserData = 1;
$external_auth = 0;
$LTIGradeMode = '';
$LTIGradeMode = 'homework';
$LTIGradeOnSubmit = 1;
$LTICheckPrior = 0;

and

cat authen_LTI_1_1.conf|grep -v "^#"|grep "\S"
$LTI{v1p1}{LMS_name} = 'Canvas';
$LTI{v1p1}{LMS_url} = 'https://canvas.wpi.edu/';
$LTI{v1p1}{preferred_source_of_username} = 'lis_person_contact_email_primary';
$LTI{v1p1}{fallback_source_of_username} = '';
$LTI{v1p1}{strip_domain_from_email} = 1;
$LTI{v1p1}{lowercase_username} = 0;
$LTI{v1p1}{preferred_source_of_student_id} = 'custom_canvas_user_login_id';

secret is set and

$LTI{v1p1}{NonceLifeTime} = 60; # in seconds
$LTI{v1p1}{OverrideSiteURL} = '';
$LTI{v1p1}{OverrideSiteProtocolDomain} = '';

anything here seem wrong ?

student crcermak has success in LTI but also has
  "timestamp" => 1737707018,
  "user_id" => "crcermak"
}
[Fri Jan 24 03:23:54.81358 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Fri Jan 24 03:23:54.81565 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced has been called for data verification
[Fri Jan 24 03:23:54.81692 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data

does this suggest tuning NonceLifeTime would help ?
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -
Anytime that you see WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has insufficent data in the debug log that means that one of the one of the oauth parameters (oauth_consumer_key, oauth_signature, oauth_nonce, or oauth_timestamp) was missing.  If any of those parameters are missing, it most likely is not a configuration issue at all that is causing the issue.  Are you sure that the instructor that created these links in Canvas actually used an "External Tool" setup for the links?  If the instructor created an "External URL" link as a Canvas module, then it will not work for LTI authentication.  Some instructor using a basic link instead of an external tool seems more likely to be the root of these issues than anything else.

Note that there is no reason to add debugging statements to the code to see this if you have debug in webwork2.mojolicious.conf turned on.  All parameters received in the request are shown in the debug log already.

If you have debug_lti_parameters turned on and are not getting the message "Nonce Expired.  Your NonceLifeTime may be too short", then tuning NonceLifeTime is probably not going to help.
In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -

I have not verified all class work but for calc 1 I have attached the canvas side.  Does this seem wrong?


The student I mentioned in today's post has both LTI success and failure within a close time period.  I was not at this students screen when LTI was turned on but this does suggest to me increasing NonceLifeTime to maybe 120 vs current 60

While canvas is cloud based, with webwork is on campus in our datacenter.

Attachment Screenshot 2025-01-24 at 7.06.55 AM.png
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -
That looks right for the Canvas external tool setup. You can try changing the NonceLifeTime and see if it helps. I doubt that it will, but it is worth a shot.
In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
Thank you Glenn. Still seems like LTI is not fully functional. Why does grade pass back work well in both 2.18 and 2.19. From what I have learned in this thread, I am not sure LTI auth has ever fully worked correctly for WPI.

Our brief history included 2.13 not able to use grade passback. I deployed the 2.15 VM from the MAA site which worked well. With 2.15, our webwork performance improved and grade pass back worked.

Seems like I need to still focus on the oauth parameters (oauth_consumer_key, oauth_signature, oauth_nonce, or oauth_timestamp) that are missing ?
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -
It sounds like something is intercepting the request from Canvas to WeBWorK and not forwarding it properly. So by the time it reaches WeBWorK it is missing parameters. Is there a proxy of some sort involved here?
In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
The only proxy that I am aware of is the reverse proxy to webwork2 service on the webwork server.

Does the webwork server with apache need any special configs outside of the like Header always set X-Permitted-Cross-Domain-Policies ?
In reply to John Eismeier

Re: First student login with 2.19 sometimes fails to create an account?

by Glenn Rice -

If you are using the conf/webwork2.apache2.4.conf file, then everything that is needed should be set.  If you aren't using that file, then you should check it for things that are needed.

In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
I am using the conf/webwork2.apach2.4.conf

Thanks again Glenn.
In reply to Glenn Rice

Re: First student login with 2.19 sometimes fails to create an account?

by John Eismeier -
One additional observation on LTI failing then working includes first mouse pic of the iframe to webwork failing, go back to canvas assignments and second mouse pic of the iframe to webwork LTI succeeds ?


[Mon Jan 27 09:34:35.85924 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Mon Jan 27 09:34:35.86161 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced has been called for data verification
[Mon Jan 27 09:34:35.86287 2025] WeBWorK::Authen::LTIAdvanced::request_has_data_for_this_verification_module: LTIAdvanced returning that it has sufficient data
[Mon Jan 27 09:34:35.86421 2025] WeBWorK::Authen::do_verify: db ok
[Mon Jan 27 09:34:35.86508 2025] WeBWorK::Authen::LTIAdvanced::get_credentials: LTIAdvanced::get_credentials has been called
[Mon Jan 27 09:34:35.86703 2025] WeBWorK::Authen::LTIAdvanced::get_credentials: LTIAdvanced::get_credentials is returning a 1
[Mon Jan 27 09:34:35.86796 2025] WeBWorK::Authen::do_verify: credentials ok
[Mon Jan 27 09:34:35.86890 2025] WeBWorK::Authen::LTIAdvanced::check_user: LTIAdvanced::check_user has been called for user_id = |jpeismeier|
[Mon Jan 27 09:34:35.93577 2025] WeBWorK::Authen::LTIAdvanced::check_user: LTIAdvanced::check_user is about to return a 1.
[Mon Jan 27 09:34:35.93755 2025] WeBWorK::Authen::do_verify: check user ok
[Mon Jan 27 09:34:35.93921 2025] WeBWorK::Authen::LTIAdvanced::verify_normal_user: LTIAdvanced::verify_normal_user called for user |jpeismeier|
[Mon Jan 27 09:34:35.94019 2025] WeBWorK::Authen::LTIAdvanced::authenticate: LTIAdvanced::authenticate called for user |jpeismeier|
[Mon Jan 27 09:34:35.94116 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ref(c) = |WeBWorK::ContentGenerator::ProblemSet|
[Mon Jan 27 09:34:35.94203 2025] WeBWorK::Authen::LTIAdvanced::authenticate: Nonce = |M94SruraGDrxjvBUbjveo9pzMmv02fdOQYS26kDkrI|
[Mon Jan 27 09:34:35.118210 2025] WeBWorK::Authen::LTIAdvanced::authenticate: c->param(oauth_signature) = |iHanfFGxqvR3kktCQy9GHpaWG7U=|
[Mon Jan 27 09:34:35.118491 2025] WeBWorK::Authen::LTIAdvanced::authenticate: context_id->|d8a1f9b296d230304b3adbc70e3f2467ef86b6c9|
[Mon Jan 27 09:34:35.118652 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_assignment_title->|WW5_Differentiation|
[Mon Jan 27 09:34:35.118815 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcome_submission_prioritize_non_tool_grade_accepted->|true|
[Mon Jan 27 09:34:35.119033 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_module_id->|169152|
[Mon Jan 27 09:34:35.119200 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_signature_method->|HMAC-SHA1|
[Mon Jan 27 09:34:35.119362 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_user_id->|21063|
[Mon Jan 27 09:34:35.119510 2025] WeBWorK::Authen::LTIAdvanced::authenticate: tool_consumer_info_product_family_code->|canvas|
[Mon Jan 27 09:34:35.119652 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_person_name_given->|John|
[Mon Jan 27 09:34:35.119800 2025] WeBWorK::Authen::LTIAdvanced::authenticate: launch_presentation_locale->|en|
[Mon Jan 27 09:34:35.119939 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lti_message_type->|basic-lti-launch-request|
[Mon Jan 27 09:34:35.120088 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_course_offering_sourcedid->|MA1021-C25-CL01|
[Mon Jan 27 09:34:35.120226 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_module_item_id->|1235334|
[Mon Jan 27 09:34:35.120376 2025] WeBWorK::Authen::LTIAdvanced::authenticate: roles->|Instructor|
[Mon Jan 27 09:34:35.120516 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_assignment_id->|391097|
[Mon Jan 27 09:34:35.120650 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcome_submission_submitted_at_accepted->|true|
[Mon Jan 27 09:34:35.120783 2025] WeBWorK::Authen::LTIAdvanced::authenticate: context_label->|MA1021 in 2025C|
[Mon Jan 27 09:34:35.120917 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_course_id->|69872|
[Mon Jan 27 09:34:35.121062 2025] WeBWorK::Authen::LTIAdvanced::authenticate: resource_link_title->|WW5_Differentiation|
[Mon Jan 27 09:34:35.121195 2025] WeBWorK::Authen::LTIAdvanced::authenticate: launch_presentation_return_url->|https://canvas.wpi.edu/courses/69872/assignments|
[Mon Jan 27 09:34:35.121327 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_enrollment_state->|active|
[Mon Jan 27 09:34:35.121493 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_workflow_state->|available|
[Mon Jan 27 09:34:35.121625 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcome_data_values_accepted->|url,text|
[Mon Jan 27 09:34:35.121759 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_assignment_points_possible->|100|
[Mon Jan 27 09:34:35.121887 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_version->|1.0|
[Mon Jan 27 09:34:35.122020 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_timestamp->|1737988456|
[Mon Jan 27 09:34:35.122180 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_person_sourcedid->|799179330|
[Mon Jan 27 09:34:35.122315 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_callback->|about:blank|
[Mon Jan 27 09:34:35.122464 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_nonce->|M94SruraGDrxjvBUbjveo9pzMmv02fdOQYS26kDkrI|
[Mon Jan 27 09:34:35.122598 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_api_domain->|canvas.wpi.edu|
[Mon Jan 27 09:34:35.122732 2025] WeBWorK::Authen::LTIAdvanced::authenticate: tool_consumer_instance_contact_email->|notifications@instructure.com|
[Mon Jan 27 09:34:35.122869 2025] WeBWorK::Authen::LTIAdvanced::authenticate: custom_canvas_user_login_id->|jpeismeier|
[Mon Jan 27 09:34:35.123026 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_ims_lis_basic_outcome_url->|https://canvas.wpi.edu/api/lti/v1/tools/5566/ext_grade_passback|
[Mon Jan 27 09:34:35.123188 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_person_name_family->|Eismeier|
[Mon Jan 27 09:34:35.123333 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_person_contact_email_primary->|jpeismeier@wpi.edu|
[Mon Jan 27 09:34:35.123511 2025] WeBWorK::Authen::LTIAdvanced::authenticate: launch_presentation_document_target->|iframe|
[Mon Jan 27 09:34:35.123656 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_consumer_key->|Webwork|
[Mon Jan 27 09:34:35.123781 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lti_version->|LTI-1p0|
[Mon Jan 27 09:34:35.123905 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_outcome_service_url->|https://canvas.wpi.edu/api/lti/v1/tools/5566/grade_passback|
[Mon Jan 27 09:34:35.124069 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_roles->|urn:lti:instrole:ims/lis/Instructor,urn:lti:instrole:ims/lis/Student,urn:lti:role:ims/lis/Instructor,urn:lti:sysrole:ims/lis/User|
[Mon Jan 27 09:34:35.124223 2025] WeBWorK::Authen::LTIAdvanced::authenticate: tool_consumer_instance_guid->|kwYfg31wBxrVjenz1JaMnqbMH9lZTAoQXBPYsd2e:canvas-lms|
[Mon Jan 27 09:34:35.124399 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcome_submission_needs_additional_review_accepted->|true|
[Mon Jan 27 09:34:35.124540 2025] WeBWorK::Authen::LTIAdvanced::authenticate: user_id->|914417c9e49c5c2fcbff68eef21ff604fb1e2e22|
[Mon Jan 27 09:34:35.124670 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcomes_tool_placement_url->|https://canvas.wpi.edu/api/lti/v1/turnitin/outcomes_placement/5566|
[Mon Jan 27 09:34:35.124810 2025] WeBWorK::Authen::LTIAdvanced::authenticate: tool_consumer_instance_name->|Worcester Polytechnic Institute|
[Mon Jan 27 09:34:35.124933 2025] WeBWorK::Authen::LTIAdvanced::authenticate: user_image->|https://canvas.wpi.edu/images/thumbnails/3897825/hwmK4YWWVgcTZFjuwxVVCZ7CrllfIalAKjmx7bgK|
[Mon Jan 27 09:34:35.125067 2025] WeBWorK::Authen::LTIAdvanced::authenticate: tool_consumer_info_version->|cloud|
[Mon Jan 27 09:34:35.125201 2025] WeBWorK::Authen::LTIAdvanced::authenticate: resource_link_id->|f7759242528ab78d08d91f7bf563c7fcc4de92d1|
[Mon Jan 27 09:34:35.125326 2025] WeBWorK::Authen::LTIAdvanced::authenticate: lis_person_name_full->|John Eismeier|
[Mon Jan 27 09:34:35.125475 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_lti_assignment_id->|5fee1e76-1285-4711-a006-ca4bf1e53b43|
[Mon Jan 27 09:34:35.125596 2025] WeBWorK::Authen::LTIAdvanced::authenticate: oauth_signature->|iHanfFGxqvR3kktCQy9GHpaWG7U=|
[Mon Jan 27 09:34:35.125723 2025] WeBWorK::Authen::LTIAdvanced::authenticate: context_title->|Calculus I|
[Mon Jan 27 09:34:35.125846 2025] WeBWorK::Authen::LTIAdvanced::authenticate: ext_outcome_result_total_score_accepted->|true|
[Mon Jan 27 09:34:35.129569 2025] WeBWorK::Authen::LTIAdvanced::authenticate: OAuth verification SUCCEEDED !!
[Mon Jan 27 09:34:35.133488 2025] WeBWorK::Authen::LTIAdvanced::verify_normal_user: auth_result=|1|
[Mon Jan 27 09:34:35.133803 2025] WeBWorK::Authen::LTIAdvanced::verify_normal_user: session_key=|CMBaE4V5mdtXm8qBDSCaWZlTM28wKlxP|.
[Mon Jan 27 09:34:35.134122 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN OK user_id=jpeismeier login_type=normal credential_source=LTIAdvanced host=10.217.64.207 port=36984 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:134.0) Gecko/20100101 Firefox/134.0'.
[Mon Jan 27 09:34:35.134806 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Mon Jan 27 09:34:35.134925 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Mon Jan 27 09:34:35.135144 2025] WeBWorK::Authen::set_params: params user='jpeismeier' key='CMBaE4V5mdtXm8qBDSCaWZlTM28wKlxP'
[Mon Jan 27 09:34:35.135276 2025] WeBWorK::Authen::verify: END VERIFY
[Mon Jan 27 09:34:35.135385 2025] WeBWorK::Authen::verify: result 1
[Mon Jan 27 09:34:35.373942 2025] WeBWorK::Authen::store_session: Saving database session. The database session contains
{
"key" => "CMBaE4V5mdtXm8qBDSCaWZlTM28wKlxP",
"session" => {},
"timestamp" => 1737988475,
"user_id" => "jpeismeier"
}


Any additional thoughts on why this could occur ?