===> Begin WeBWorK::dispatch() <===

[Tue Mar 18 16:15:04.394328 2025] (eval): Hi, I'm the new dispatcher!
[Tue Mar 18 16:15:04.394390 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:04.394433 2025] (eval): Okay, I got some basic information:
[Tue Mar 18 16:15:04.394472 2025] (eval): The site location is /webwork2
[Tue Mar 18 16:15:04.394510 2025] (eval): The request method is GET
[Tue Mar 18 16:15:04.394616 2025] (eval): The URI is /webwork2/Test_Course_5/logout
[Tue Mar 18 16:15:04.394659 2025] (eval): The argument string is effectiveUser=qiy497
[Tue Mar 18 16:15:04.394697 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:04.394774 2025] (eval): The path is /Test_Course_5/logout/
[Tue Mar 18 16:15:04.394842 2025] (eval): The current route is logout
[Tue Mar 18 16:15:04.394882 2025] (eval): Here is some information about this route:
[Tue Mar 18 16:15:04.394929 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::Logout
[Tue Mar 18 16:15:04.394966 2025] (eval): This route has the following captures:
[Tue Mar 18 16:15:04.395007 2025] (eval): 	action => go
[Tue Mar 18 16:15:04.395043 2025] (eval): 	courseID => Test_Course_5
[Tue Mar 18 16:15:04.395082 2025] (eval): 	controller => Logout
[Tue Mar 18 16:15:04.395119 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:04.395156 2025] (eval): Now we want to look at the parameters we got.
[Tue Mar 18 16:15:04.395211 2025] (eval): The raw params:
[Tue Mar 18 16:15:04.395326 2025] (eval): 	effectiveUser => "qiy497"
[Tue Mar 18 16:15:04.395395 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:04.395453 2025] (eval): We need to get a course environment (with or without a courseID!)
[Tue Mar 18 16:15:04.402020 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x563b74e75620)
[Tue Mar 18 16:15:04.402479 2025] (eval): Using authentication module WeBWorK::Authen::LTIAdvantage: WeBWorK::Authen::LTIAdvantage=HASH(0x563b74f54f88)
[Tue Mar 18 16:15:04.402581 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Tue Mar 18 16:15:04.402637 2025] (eval): ...we can create a database object...
[Tue Mar 18 16:15:04.411895 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x563b74e758a8))
[Tue Mar 18 16:15:04.412055 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:04.412115 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage has been called for data verification
[Tue Mar 18 16:15:04.412170 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage returning that it has insufficent data
[Tue Mar 18 16:15:04.412311 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:04.412371 2025] WeBWorK::Authen::do_verify: db ok
[Tue Mar 18 16:15:04.412418 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::LDAP=HASH(0x563b74f55018)
[Tue Mar 18 16:15:04.412850 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="0y2TH52Bp3uESDUf3t0vt8bSHnvAOLSw", timestamp="1742332503"
[Tue Mar 18 16:15:04.412935 2025] WeBWorK::Authen::get_credentials: credential source: "cookie", user: "qiy497", key: "0y2TH52Bp3uESDUf3t0vt8bSHnvAOLSw", timestamp: "1742332503"
[Tue Mar 18 16:15:04.412991 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Mar 18 16:15:04.414166 2025] WeBWorK::Authen::do_verify: check user ok
[Tue Mar 18 16:15:04.415024 2025] WeBWorK::Authen::verify_normal_user: sessionExists='1' keyMatches='1' timestampValid='1'
[Tue Mar 18 16:15:04.415212 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="0y2TH52Bp3uESDUf3t0vt8bSHnvAOLSw", timestamp="1742332503"
[Tue Mar 18 16:15:04.415286 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='1' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Tue Mar 18 16:15:04.415415 2025] WeBWorK::Authen::set_params: params user='qiy497' key='0y2TH52Bp3uESDUf3t0vt8bSHnvAOLSw'
[Tue Mar 18 16:15:04.415482 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Mar 18 16:15:04.415522 2025] WeBWorK::Authen::verify: result 1
[Tue Mar 18 16:15:04.415587 2025] (eval): Hi, qiy497, glad you made it.
[Tue Mar 18 16:15:04.416588 2025] (eval): Now we deal with the effective user:
[Tue Mar 18 16:15:04.416682 2025] (eval): userID=qiy497 eUserID=qiy497
[Tue Mar 18 16:15:04.417595 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGGED OUT user_id=qiy497 login_type=normal credential_source=cookie host=10.2.16.47 port=52108 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'.
[Tue Mar 18 16:15:04.423621 2025] WeBWorK::Authen::store_session: Deleting database session.
[Tue Mar 18 16:15:04.424262 2025] WeBWorK::Authen::store_session: The cookie session is expired.
[Tue Mar 18 16:15:49.114264 2025] (eval): 

===> Begin WeBWorK::dispatch() <===

[Tue Mar 18 16:15:49.114698 2025] (eval): Hi, I'm the new dispatcher!
[Tue Mar 18 16:15:49.114768 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:49.114840 2025] (eval): Okay, I got some basic information:
[Tue Mar 18 16:15:49.114886 2025] (eval): The site location is /webwork2
[Tue Mar 18 16:15:49.114924 2025] (eval): The request method is POST
[Tue Mar 18 16:15:49.115158 2025] (eval): The URI is /webwork2/ltiadvantage/login
[Tue Mar 18 16:15:49.115263 2025] (eval): The argument string is iss=https%3A%2F%2Fcanvas.instructure.com&login_hint=17d8f0db792031911296ec4232ef4c3d73f856f5&client_id=239550000000000143&lti_deployment_id=208%3A08d97cdd50609c3c84da93ae5d30f0e49933da97&target_link_uri=https%3A%2F%2Fwebworkdev01.utsarr.net%2Fwebwork2%2Fltiadvantage%2Fcontent_selection&lti_message_hint=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ2ZXJpZmllciI6IjEyNTM5YWVlYzI5Mzg2MDA0M2U5MTYxMWQwZWJkOWE5NmQyNWQwNmU5OGZjYjI4NmNiYWMxMDM0NjA1NTA4M2U3NTk5Y2UzMGU3MDM1NjVkODU3ZWFjYjIxMDhkMjQ3ZjVmZTg4ZDIxOGUzNjk3NjcyYzRkMTE3NWQzZTFiZmJmIiwiY2FudmFzX2RvbWFpbiI6InV0c2EtZGV2Lmluc3RydWN0dXJlLmNvbSIsImNvbnRleHRfdHlwZSI6IkNvdXJzZSIsImNvbnRleHRfaWQiOjIzOTU1MDAwMDAwMDAzMTczOCwiY2FudmFzX2xvY2FsZSI6ImVuIiwiaW5jbHVkZV9zdG9yYWdlX3RhcmdldCI6dHJ1ZSwiZXhwIjoxNzQyMzMyODQ4fQ.MQhkzBhMIXvd62NwhM2vrm3M3Zk1e_S79SubT6vKAoI&canvas_environment=prod&canvas_region=us-west-2&lti_storage_target=post_message_forwarding
[Tue Mar 18 16:15:49.115315 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:49.115434 2025] (eval): The path is /ltiadvantage/login/
[Tue Mar 18 16:15:49.115521 2025] (eval): The current route is ltiadvantage_login
[Tue Mar 18 16:15:49.115567 2025] (eval): Here is some information about this route:
[Tue Mar 18 16:15:49.115629 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::LTIAdvantage
[Tue Mar 18 16:15:49.115680 2025] (eval): This route has the following captures:
[Tue Mar 18 16:15:49.115730 2025] (eval): 	controller => LTIAdvantage
[Tue Mar 18 16:15:49.115769 2025] (eval): 	action => login
[Tue Mar 18 16:15:49.115806 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:49.115842 2025] (eval): Now we want to look at the parameters we got.
[Tue Mar 18 16:15:49.115878 2025] (eval): The raw params:
[Tue Mar 18 16:15:49.116039 2025] (eval): 	target_link_uri => "https://webworkdev01.utsarr.net/webwork2/ltiadvantage/content_selection"
[Tue Mar 18 16:15:49.116098 2025] (eval): 	canvas_region => "us-west-2"
[Tue Mar 18 16:15:49.116142 2025] (eval): 	iss => "https://canvas.instructure.com"
[Tue Mar 18 16:15:49.116184 2025] (eval): 	lti_message_hint => "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ2ZXJpZmllciI6IjEyNTM5YWVlYzI5Mzg2MDA0M2U5MTYxMWQwZWJkOWE5NmQyNWQwNmU5OGZjYjI4NmNiYWMxMDM0NjA1NTA4M2U3NTk5Y2UzMGU3MDM1NjVkODU3ZWFjYjIxMDhkMjQ3ZjVmZTg4ZDIxOGUzNjk3NjcyYzRkMTE3NWQzZTFiZmJmIiwiY2FudmFzX2RvbWFpbiI6InV0c2EtZGV2Lmluc3RydWN0dXJlLmNvbSIsImNvbnRleHRfdHlwZSI6IkNvdXJzZSIsImNvbnRleHRfaWQiOjIzOTU1MDAwMDAwMDAzMTczOCwiY2FudmFzX2xvY2FsZSI6ImVuIiwiaW5jbHVkZV9zdG9yYWdlX3RhcmdldCI6dHJ1ZSwiZXhwIjoxNzQyMzMyODQ4fQ.MQhkzBhMIXvd62NwhM2vrm3M3Zk1e_S79SubT6vKAoI"
[Tue Mar 18 16:15:49.116252 2025] (eval): 	login_hint => "17d8f0db792031911296ec4232ef4c3d73f856f5"
[Tue Mar 18 16:15:49.116296 2025] (eval): 	canvas_environment => "prod"
[Tue Mar 18 16:15:49.116335 2025] (eval): 	client_id => "239550000000000143"
[Tue Mar 18 16:15:49.116376 2025] (eval): 	lti_storage_target => "post_message_forwarding"
[Tue Mar 18 16:15:49.116415 2025] (eval): 	lti_deployment_id => "208:08d97cdd50609c3c84da93ae5d30f0e49933da97"
[Tue Mar 18 16:15:49.116453 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:49.142604 2025] (eval): We need to get a course environment (with or without a courseID!)
[Tue Mar 18 16:15:49.147904 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x5651fa060b08)
[Tue Mar 18 16:15:49.184591 2025] (eval): Using authentication module WeBWorK::Authen::LTIAdvantage: WeBWorK::Authen::LTIAdvantage=HASH(0x5651f9fe4c80)
[Tue Mar 18 16:15:49.184727 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Tue Mar 18 16:15:49.184801 2025] (eval): ...we can create a database object...
[Tue Mar 18 16:15:49.213277 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x5651f49544f8))
[Tue Mar 18 16:15:49.213554 2025] WeBWorK::Authen::LTIAdvantage::verify: The LTI Advantage login route was accessed with the appropriate parameters.
[Tue Mar 18 16:15:50.7376 2025] (eval): 

===> Begin WeBWorK::dispatch() <===

[Tue Mar 18 16:15:50.7572 2025] (eval): Hi, I'm the new dispatcher!
[Tue Mar 18 16:15:50.7635 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.7694 2025] (eval): Okay, I got some basic information:
[Tue Mar 18 16:15:50.7739 2025] (eval): The site location is /webwork2
[Tue Mar 18 16:15:50.7787 2025] (eval): The request method is POST
[Tue Mar 18 16:15:50.7901 2025] (eval): The URI is /webwork2/ltiadvantage/launch
[Tue Mar 18 16:15:50.7958 2025] (eval): The argument string is utf8=%E2%9C%93&authenticity_token=5hei…tNmj6gHG-kTU0WMNSA&state=5bb3881ca2e36f202f3b37b58997a83c17ea3ccb4d6e8c91eab3e6b5c4368e7f&lti_storage_target=post_message_forwarding
[Tue Mar 18 16:15:50.8037 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.8122 2025] (eval): The path is /ltiadvantage/launch/
[Tue Mar 18 16:15:50.8203 2025] (eval): The current route is ltiadvantage_launch
[Tue Mar 18 16:15:50.8264 2025] (eval): Here is some information about this route:
[Tue Mar 18 16:15:50.8312 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::LTIAdvantage
[Tue Mar 18 16:15:50.8351 2025] (eval): This route has the following captures:
[Tue Mar 18 16:15:50.8396 2025] (eval): 	action => launch
[Tue Mar 18 16:15:50.8435 2025] (eval): 	controller => LTIAdvantage
[Tue Mar 18 16:15:50.8483 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.8521 2025] (eval): Now we want to look at the parameters we got.
[Tue Mar 18 16:15:50.8557 2025] (eval): The raw params:
[Tue Mar 18 16:15:50.8670 2025] (eval): 	utf8 => "✓"
[Tue Mar 18 16:15:50.8731 2025] (eval): 	id_token => "eyJ0…MNSA"
[Tue Mar 18 16:15:50.8821 2025] (eval): 	state => "5bb3881ca2e36f202f3b37b58997a83c17ea3ccb4d6e8c91eab3e6b5c4368e7f"
[Tue Mar 18 16:15:50.8867 2025] (eval): 	lti_storage_target => "post_message_forwarding"
[Tue Mar 18 16:15:50.8915 2025] (eval): 	authenticity_token => "5heiCOIgLH8vnmonuEMk+vFYyZ4mSZRtVfLXSPGvlaDRRdNPqXB9Lx/NG3POG2KAwBufyUQYu1kaxL8Pi+fy2g=="
[Tue Mar 18 16:15:50.8958 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.60919 2025] (eval): We need to get a course environment (with or without a courseID!)
[Tue Mar 18 16:15:50.66838 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x5651fa3d1ed0)
[Tue Mar 18 16:15:50.67321 2025] (eval): Using authentication module WeBWorK::Authen::LTIAdvantage: WeBWorK::Authen::LTIAdvantage=HASH(0x5651fa58b3f8)
[Tue Mar 18 16:15:50.67438 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Tue Mar 18 16:15:50.67503 2025] (eval): ...we can create a database object...
[Tue Mar 18 16:15:50.77050 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x5651fa3ee1e8))
[Tue Mar 18 16:15:50.77231 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:50.77306 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage has been called for data verification
[Tue Mar 18 16:15:50.77376 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage returning that it has sufficient data
[Tue Mar 18 16:15:50.77435 2025] WeBWorK::Authen::do_verify: db ok
[Tue Mar 18 16:15:50.77486 2025] WeBWorK::Authen::LTIAdvantage::get_credentials: LTIAdvantage::get_credentials has been called
[Tue Mar 18 16:15:50.78067 2025] WeBWorK::Authen::LTIAdvantage::get_credentials: LTIAdvantange::get_credentials is returning 1.
[Tue Mar 18 16:15:50.78152 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Mar 18 16:15:50.78247 2025] WeBWorK::Authen::LTIAdvantage::check_user: LTIAdvantange::check_user has been called for user_id = |qiy497|
[Tue Mar 18 16:15:50.80449 2025] WeBWorK::Authen::LTIAdvantage::check_user: LTIAdvantange::check_user is about to return a 1.
[Tue Mar 18 16:15:50.80546 2025] WeBWorK::Authen::do_verify: check user ok
[Tue Mar 18 16:15:50.80605 2025] WeBWorK::Authen::LTIAdvantage::verify_normal_user: LTIAdvantage::verify_normal_user called for user |qiy497|
[Tue Mar 18 16:15:50.80656 2025] WeBWorK::Authen::LTIAdvantage::authenticate: LTIAdvantange::authenticate called for user |qiy497|
[Tue Mar 18 16:15:50.88334 2025] WeBWorK::Authen::LTIAdvantage::verify_normal_user: auth_result=|1|
[Tue Mar 18 16:15:50.88561 2025] WeBWorK::Authen::LTIAdvantage::verify_normal_user: session_key=|kIicWxrAYukjOKR5srUrvwyDBBkWhw2B|.
[Tue Mar 18 16:15:50.88771 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN OK user_id=qiy497 login_type=normal credential_source=LTIAdvantage host=10.2.16.47 port=35354 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'.
[Tue Mar 18 16:15:50.89375 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Tue Mar 18 16:15:50.89495 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Tue Mar 18 16:15:50.89720 2025] WeBWorK::Authen::set_params: params user='qiy497' key='kIicWxrAYukjOKR5srUrvwyDBBkWhw2B'
[Tue Mar 18 16:15:50.89842 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Mar 18 16:15:50.89893 2025] WeBWorK::Authen::verify: result 1
[Tue Mar 18 16:15:50.89972 2025] (eval): Hi, qiy497, glad you made it.
[Tue Mar 18 16:15:50.90981 2025] (eval): Now we deal with the effective user:
[Tue Mar 18 16:15:50.91079 2025] (eval): userID=qiy497 eUserID=qiy497
[Tue Mar 18 16:15:50.91698 2025] WeBWorK::Authen::store_session: Saving database session.  The database session contains
{
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "session" => {},
  "timestamp" => 1742332550,
  "user_id" => "qiy497"
}
[Tue Mar 18 16:15:50.95005 2025] WeBWorK::Authen::store_session: The cookie session contains
{
  "expiration" => 1800,
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "timestamp" => 1742332550,
  "user_id" => "qiy497"
}
[Tue Mar 18 16:15:50.106594 2025] (eval): 

===> Begin WeBWorK::dispatch() <===

[Tue Mar 18 16:15:50.106706 2025] (eval): Hi, I'm the new dispatcher!
[Tue Mar 18 16:15:50.106759 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.106801 2025] (eval): Okay, I got some basic information:
[Tue Mar 18 16:15:50.106848 2025] (eval): The site location is /webwork2
[Tue Mar 18 16:15:50.106886 2025] (eval): The request method is GET
[Tue Mar 18 16:15:50.106971 2025] (eval): The URI is /webwork2/ltiadvantage/content_selection
[Tue Mar 18 16:15:50.107018 2025] (eval): The argument string is courseID=Test_Course_5&effectiveUser=qiy497&initial_request=1&deep_link_return_url=https%3A%2F%2Futsa-dev.instructure.com%2Fcourses%2F31738%2Fdeep_linking_response%3Fdata%3DeyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJub25jZSI6IjIzMzhlZDBkLTcwZGMtNDUwMy1hN2Q3LTRmMGJkZGNmNTYwNSIsIm1vZGFsIjp0cnVlLCJwbGFjZW1lbnQiOiJhc3NpZ25tZW50X3NlbGVjdGlvbiJ9.D6E_n482sQc6cnk7rPmGcdyKrT8sZs44plKq5guVFDg&accept_multiple=0
[Tue Mar 18 16:15:50.107057 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.107124 2025] (eval): The path is /ltiadvantage/content_selection/
[Tue Mar 18 16:15:50.107178 2025] (eval): The current route is ltiadvantage_content_selection
[Tue Mar 18 16:15:50.107253 2025] (eval): Here is some information about this route:
[Tue Mar 18 16:15:50.107303 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::LTIAdvantage
[Tue Mar 18 16:15:50.107343 2025] (eval): This route has the following captures:
[Tue Mar 18 16:15:50.107382 2025] (eval): 	action => content_selection
[Tue Mar 18 16:15:50.107418 2025] (eval): 	controller => LTIAdvantage
[Tue Mar 18 16:15:50.107458 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.107495 2025] (eval): Now we want to look at the parameters we got.
[Tue Mar 18 16:15:50.107531 2025] (eval): The raw params:
[Tue Mar 18 16:15:50.107639 2025] (eval): 	deep_link_return_url => "https://utsa-dev.instructure.com/courses/31738/deep_linking_response?data=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJub25jZSI6IjIzMzhlZDBkLTcwZGMtNDUwMy1hN2Q3LTRmMGJkZGNmNTYwNSIsIm1vZGFsIjp0cnVlLCJwbGFjZW1lbnQiOiJhc3NpZ25tZW50X3NlbGVjdGlvbiJ9.D6E_n482sQc6cnk7rPmGcdyKrT8sZs44plKq5guVFDg"
[Tue Mar 18 16:15:50.107691 2025] (eval): 	initial_request => "1"
[Tue Mar 18 16:15:50.107735 2025] (eval): 	courseID => "Test_Course_5"
[Tue Mar 18 16:15:50.107780 2025] (eval): 	effectiveUser => "qiy497"
[Tue Mar 18 16:15:50.107821 2025] (eval): 	accept_multiple => "0"
[Tue Mar 18 16:15:50.107859 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:50.107929 2025] (eval): We need to get a course environment (with or without a courseID!)
[Tue Mar 18 16:15:50.113884 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x5651fa5456f0)
[Tue Mar 18 16:15:50.114281 2025] (eval): Using authentication module WeBWorK::Authen::LTIAdvantage: WeBWorK::Authen::LTIAdvantage=HASH(0x5651fa61f410)
[Tue Mar 18 16:15:50.114372 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Tue Mar 18 16:15:50.114428 2025] (eval): ...we can create a database object...
[Tue Mar 18 16:15:50.123356 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x5651fa543308))
[Tue Mar 18 16:15:50.123484 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:50.123540 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage has been called for data verification
[Tue Mar 18 16:15:50.123596 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage returning that it has insufficent data
[Tue Mar 18 16:15:50.148532 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:50.148646 2025] WeBWorK::Authen::do_verify: db ok
[Tue Mar 18 16:15:50.148717 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::LDAP=HASH(0x5651fa550160)
[Tue Mar 18 16:15:50.149169 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp="1742332550"
[Tue Mar 18 16:15:50.149291 2025] WeBWorK::Authen::get_credentials: credential source: "cookie", user: "qiy497", key: "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp: "1742332550"
[Tue Mar 18 16:15:50.149343 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Mar 18 16:15:50.150273 2025] WeBWorK::Authen::do_verify: check user ok
[Tue Mar 18 16:15:50.151049 2025] WeBWorK::Authen::verify_normal_user: sessionExists='1' keyMatches='1' timestampValid='1'
[Tue Mar 18 16:15:50.151233 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp="1742332550"
[Tue Mar 18 16:15:50.151305 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='1' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Tue Mar 18 16:15:50.151426 2025] WeBWorK::Authen::set_params: params user='qiy497' key='kIicWxrAYukjOKR5srUrvwyDBBkWhw2B'
[Tue Mar 18 16:15:50.151489 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Mar 18 16:15:50.151529 2025] WeBWorK::Authen::verify: result 1
[Tue Mar 18 16:15:50.151586 2025] (eval): Hi, qiy497, glad you made it.
[Tue Mar 18 16:15:50.152558 2025] (eval): Now we deal with the effective user:
[Tue Mar 18 16:15:50.152652 2025] (eval): userID=qiy497 eUserID=qiy497
[Tue Mar 18 16:15:50.159534 2025] WeBWorK::Authen::store_session: Saving database session.  The database session contains
{
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "session" => {},
  "timestamp" => 1742332550,
  "user_id" => "qiy497"
}
[Tue Mar 18 16:15:50.162502 2025] WeBWorK::Authen::store_session: The cookie session contains
{
  "expiration" => 1800,
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "timestamp" => 1742332550,
  "user_id" => "qiy497"
}
[Tue Mar 18 16:15:51.325764 2025] WeBWorK::Authen::LTIAdvantage::SubmitGrade::warning: Failed to obtain access token from LMS:
Bad Request
[Tue Mar 18 16:15:51.890972 2025] (eval): 

===> Begin WeBWorK::dispatch() <===

[Tue Mar 18 16:15:51.891228 2025] (eval): Hi, I'm the new dispatcher!
[Tue Mar 18 16:15:51.891318 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:51.891365 2025] (eval): Okay, I got some basic information:
[Tue Mar 18 16:15:51.891418 2025] (eval): The site location is /webwork2
[Tue Mar 18 16:15:51.891461 2025] (eval): The request method is POST
[Tue Mar 18 16:15:51.891581 2025] (eval): The URI is /webwork2/ltiadvantage/content_selection
[Tue Mar 18 16:15:51.891628 2025] (eval): The argument string is user=qiy497&effectiveUser=qiy497&courseID=Test_Course_5&deep_link_return_url=https%3A%2F%2Futsa-dev.instructure.com%2Fcourses%2F31738%2Fdeep_linking_response%3Fdata%3DeyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJub25jZSI6IjIzMzhlZDBkLTcwZGMtNDUwMy1hN2Q3LTRmMGJkZGNmNTYwNSIsIm1vZGFsIjp0cnVlLCJwbGFjZW1lbnQiOiJhc3NpZ25tZW50X3NlbGVjdGlvbiJ9.D6E_n482sQc6cnk7rPmGcdyKrT8sZs44plKq5guVFDg&accept_multiple=0&selected_sets=01_LinearSystem
[Tue Mar 18 16:15:51.891668 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:51.891757 2025] (eval): The path is /ltiadvantage/content_selection/
[Tue Mar 18 16:15:51.891819 2025] (eval): The current route is ltiadvantage_content_selection
[Tue Mar 18 16:15:51.891866 2025] (eval): Here is some information about this route:
[Tue Mar 18 16:15:51.891919 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::LTIAdvantage
[Tue Mar 18 16:15:51.891967 2025] (eval): This route has the following captures:
[Tue Mar 18 16:15:51.892006 2025] (eval): 	action => content_selection
[Tue Mar 18 16:15:51.892043 2025] (eval): 	controller => LTIAdvantage
[Tue Mar 18 16:15:51.892079 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:51.892126 2025] (eval): Now we want to look at the parameters we got.
[Tue Mar 18 16:15:51.892171 2025] (eval): The raw params:
[Tue Mar 18 16:15:51.892322 2025] (eval): 	user => "qiy497"
[Tue Mar 18 16:15:51.892386 2025] (eval): 	deep_link_return_url => "https://utsa-dev.instructure.com/courses/31738/deep_linking_response?data=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJub25jZSI6IjIzMzhlZDBkLTcwZGMtNDUwMy1hN2Q3LTRmMGJkZGNmNTYwNSIsIm1vZGFsIjp0cnVlLCJwbGFjZW1lbnQiOiJhc3NpZ25tZW50X3NlbGVjdGlvbiJ9.D6E_n482sQc6cnk7rPmGcdyKrT8sZs44plKq5guVFDg"
[Tue Mar 18 16:15:51.892439 2025] (eval): 	courseID => "Test_Course_5"
[Tue Mar 18 16:15:51.892490 2025] (eval): 	effectiveUser => "qiy497"
[Tue Mar 18 16:15:51.892535 2025] (eval): 	selected_sets => "01_LinearSystem"
[Tue Mar 18 16:15:51.892582 2025] (eval): 	accept_multiple => "0"
[Tue Mar 18 16:15:51.892620 2025] (eval): --------------------------------------------------------------------------------
[Tue Mar 18 16:15:51.892704 2025] (eval): We need to get a course environment (with or without a courseID!)
[Tue Mar 18 16:15:51.899061 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x5651fa545678)
[Tue Mar 18 16:15:51.899515 2025] (eval): Using authentication module WeBWorK::Authen::LTIAdvantage: WeBWorK::Authen::LTIAdvantage=HASH(0x5651fa9e3500)
[Tue Mar 18 16:15:51.899613 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Tue Mar 18 16:15:51.899666 2025] (eval): ...we can create a database object...
[Tue Mar 18 16:15:51.909564 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x5651fa934ad8))
[Tue Mar 18 16:15:51.909729 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:51.909796 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage has been called for data verification
[Tue Mar 18 16:15:51.909853 2025] WeBWorK::Authen::LTIAdvantage::request_has_data_for_this_verification_module: LTIAdvantage returning that it has insufficent data
[Tue Mar 18 16:15:51.909983 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Tue Mar 18 16:15:51.910048 2025] WeBWorK::Authen::do_verify: db ok
[Tue Mar 18 16:15:51.910096 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::LDAP=HASH(0x5651fa9aada8)
[Tue Mar 18 16:15:51.910509 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp="1742332550"
[Tue Mar 18 16:15:51.910607 2025] WeBWorK::Authen::get_credentials: credential source: "cookie", user: "qiy497", key: "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp: "1742332550"
[Tue Mar 18 16:15:51.910653 2025] WeBWorK::Authen::do_verify: credentials ok
[Tue Mar 18 16:15:51.911847 2025] WeBWorK::Authen::do_verify: check user ok
[Tue Mar 18 16:15:51.912705 2025] WeBWorK::Authen::verify_normal_user: sessionExists='1' keyMatches='1' timestampValid='1'
[Tue Mar 18 16:15:51.912886 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Returning userID="qiy497", key="kIicWxrAYukjOKR5srUrvwyDBBkWhw2B", timestamp="1742332550"
[Tue Mar 18 16:15:51.912962 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='1' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Tue Mar 18 16:15:51.913096 2025] WeBWorK::Authen::set_params: params user='qiy497' key='kIicWxrAYukjOKR5srUrvwyDBBkWhw2B'
[Tue Mar 18 16:15:51.913164 2025] WeBWorK::Authen::verify: END VERIFY
[Tue Mar 18 16:15:51.913220 2025] WeBWorK::Authen::verify: result 1
[Tue Mar 18 16:15:51.913283 2025] (eval): Hi, qiy497, glad you made it.
[Tue Mar 18 16:15:51.914322 2025] (eval): Now we deal with the effective user:
[Tue Mar 18 16:15:51.914418 2025] (eval): userID=qiy497 eUserID=qiy497
[Tue Mar 18 16:15:51.922037 2025] WeBWorK::Authen::store_session: Saving database session.  The database session contains
{
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "session" => {},
  "timestamp" => 1742332551,
  "user_id" => "qiy497"
}
[Tue Mar 18 16:15:51.925072 2025] WeBWorK::Authen::store_session: The cookie session contains
{
  "expiration" => 1800,
  "key" => "kIicWxrAYukjOKR5srUrvwyDBBkWhw2B",
  "timestamp" => 1742332551,
  "user_id" => "qiy497"
}