Hi everyone,
We’ve encountered login issues affecting some faculty and students (not everyone). Although we upgraded to version 2.19 yesterday (Feb 4, 2025), the problem was first reported on Feb 2.
Below is a sample from the debug.log. Any insights on what might be causing this issue would be greatly appreciated.
Thanks for your help!
***Failed login log***
===> Begin WeBWorK::dispatch() <===
[Thu Feb 06 11:02:17.544661 2025] (eval): Hi, I'm the new dispatcher!
[Thu Feb 06 11:02:17.544745 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 11:02:17.544800 2025] (eval): Okay, I got some basic information:
[Thu Feb 06 11:02:17.544849 2025] (eval): The site location is /webwork2
[Thu Feb 06 11:02:17.544899 2025] (eval): The request method is POST
[Thu Feb 06 11:02:17.545026 2025] (eval): The URI is /webwork2/MA114_S25_JBazant_C13
[Thu Feb 06 11:02:17.545082 2025] (eval): The argument string is submit=Log+In+Again&user=jbazant&passwd=Jbazant%40
[Thu Feb 06 11:02:17.545136 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 11:02:17.545222 2025] (eval): The path is /MA114_S25_JBazant_C13/
[Thu Feb 06 11:02:17.545308 2025] (eval): The current route is set_list
[Thu Feb 06 11:02:17.545363 2025] (eval): Here is some information about this route:
[Thu Feb 06 11:02:17.545420 2025] (eval): The display module for this route is WeBWorK::ContentGenerator::ProblemSets
[Thu Feb 06 11:02:17.545472 2025] (eval): This route has the following captures:
[Thu Feb 06 11:02:17.545521 2025] (eval): controller => ProblemSets
[Thu Feb 06 11:02:17.545579 2025] (eval): courseID => MA114_S25_JBazant_C13
[Thu Feb 06 11:02:17.545633 2025] (eval): action => go
[Thu Feb 06 11:02:17.545688 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 11:02:17.545746 2025] (eval): Now we want to look at the parameters we got.
[Thu Feb 06 11:02:17.545794 2025] (eval): The raw params:
[Thu Feb 06 11:02:17.545906 2025] (eval): submit => "Log In Again"
[Thu Feb 06 11:02:17.545964 2025] (eval): passwd => **********
[Thu Feb 06 11:02:17.546035 2025] (eval): user => "jbazant"
[Thu Feb 06 11:02:17.546086 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 11:02:17.546148 2025] (eval): We need to get a course environment (with or without a courseID!)
[Thu Feb 06 11:02:17.553156 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x6376f30c6438)
[Thu Feb 06 11:02:17.553652 2025] (eval): Using authentication module WeBWorK::Authen::Basic_TheLastOption: WeBWorK::Authen::Basic_TheLastOption=HASH(0x6376f30c6300)
[Thu Feb 06 11:02:17.553763 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Thu Feb 06 11:02:17.553832 2025] (eval): ...we can create a database object...
[Thu Feb 06 11:02:17.566778 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x6376f30c61e0))
[Thu Feb 06 11:02:17.566922 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Thu Feb 06 11:02:17.567086 2025] WeBWorK::Authen::do_verify: db ok
[Thu Feb 06 11:02:17.567175 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::Basic_TheLastOption=HASH(0x6376f30c6300)
[Thu Feb 06 11:02:17.567865 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Thu Feb 06 11:02:17.568002 2025] WeBWorK::Authen::get_credentials: credential source: "params", user: "jbazant" key: "###UNDEF###"
[Thu Feb 06 11:02:17.568067 2025] WeBWorK::Authen::do_verify: credentials ok
[Thu Feb 06 11:02:17.569352 2025] WeBWorK::Authen::do_verify: check user ok
[Thu Feb 06 11:02:17.570231 2025] WeBWorK::Authen::verify_normal_user: sessionExists='0' keyMatches='###UNDEF###' timestampValid='###UNDEF###'
[Thu Feb 06 11:02:17.573303 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'AUTH WWDB: password accepted user_id=jbazant login_type=normal credential_source=params host=100.37.131.215 port=59732 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36'.
[Thu Feb 06 11:02:17.574738 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN FAILED user not allowed course access user_id=jbazant login_type=normal credential_source=params host=100.37.131.215 port=59732 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36'.
[Thu Feb 06 11:02:17.575167 2025] WeBWorK::Authen::verify: END VERIFY
[Thu Feb 06 11:02:17.575233 2025] WeBWorK::Authen::verify: result 0
[Thu Feb 06 11:02:17.575315 2025] (eval): Bad news: authentication failed!
[Thu Feb 06 11:02:17.575366 2025] (eval): Rendering WeBWorK::ContentGenerator::Login
[Thu Feb 06 11:02:17.582859 2025] WeBWorK::Authen::store_session: Deleting database session.
[Thu Feb 06 11:02:17.583480 2025] WeBWorK::Authen::store_session: The cookie session is expired.
***Successful login log (for comparison with the above, missing the first few line of the dispatcher but it is similar to the above)***
[Thu Feb 06 10:56:08.362892 2025] (eval): action => go
[Thu Feb 06 10:56:08.362948 2025] (eval): courseID => MA114_S25_JBazant_C13
[Thu Feb 06 10:56:08.363008 2025] (eval): controller => ProblemSets
[Thu Feb 06 10:56:08.363059 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 10:56:08.363107 2025] (eval): Now we want to look at the parameters we got.
[Thu Feb 06 10:56:08.363157 2025] (eval): The raw params:
[Thu Feb 06 10:56:08.363266 2025] (eval): passwd => **********
[Thu Feb 06 10:56:08.363327 2025] (eval): user => "admin2"
[Thu Feb 06 10:56:08.363377 2025] (eval): --------------------------------------------------------------------------------
[Thu Feb 06 10:56:08.363434 2025] (eval): We need to get a course environment (with or without a courseID!)
[Thu Feb 06 10:56:08.369683 2025] (eval): Here's the course environment: WeBWorK::CourseEnvironment=HASH(0x6376f2b24000)
[Thu Feb 06 10:56:08.370192 2025] (eval): Using authentication module WeBWorK::Authen::Basic_TheLastOption: WeBWorK::Authen::Basic_TheLastOption=HASH(0x6376f2b311f0)
[Thu Feb 06 10:56:08.370310 2025] (eval): We got a courseID from the route, now we can do some stuff:
[Thu Feb 06 10:56:08.370393 2025] (eval): ...we can create a database object...
[Thu Feb 06 10:56:08.382875 2025] (eval): (here's the DB handle: WeBWorK::DB=HASH(0x6376f27ad6e0))
[Thu Feb 06 10:56:08.383026 2025] WeBWorK::Authen::verify: BEGIN VERIFY
[Thu Feb 06 10:56:08.383104 2025] WeBWorK::Authen::do_verify: db ok
[Thu Feb 06 10:56:08.383177 2025] WeBWorK::Authen::get_credentials: self is WeBWorK::Authen::Basic_TheLastOption=HASH(0x6376f2b311f0)
[Thu Feb 06 10:56:08.383898 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Thu Feb 06 10:56:08.384041 2025] WeBWorK::Authen::get_credentials: credential source: "params", user: "admin2" key: "###UNDEF###"
[Thu Feb 06 10:56:08.384105 2025] WeBWorK::Authen::do_verify: credentials ok
[Thu Feb 06 10:56:08.385445 2025] WeBWorK::Authen::do_verify: check user ok
[Thu Feb 06 10:56:08.386291 2025] WeBWorK::Authen::verify_normal_user: sessionExists='0' keyMatches='###UNDEF###' timestampValid='###UNDEF###'
[Thu Feb 06 10:56:08.389355 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'AUTH WWDB: password accepted user_id=admin2 login_type=normal credential_source=params host=100.37.131.215 port=33926 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36'.
[Thu Feb 06 10:56:08.392689 2025] WeBWorK::Authen::write_log_entry: Writing to login log: 'LOGIN OK user_id=admin2 login_type=normal credential_source=params host=100.37.131.215 port=33926 UA=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36'.
[Thu Feb 06 10:56:08.393061 2025] WeBWorK::Authen::fetchCookie: fetchCookie: Session cookie does not contain valid information. Returning nothing.
[Thu Feb 06 10:56:08.393131 2025] WeBWorK::Authen::maybe_send_cookie: used_cookie='' unused_valid_cookie='' user_requests_cookie='0' session_management_via_cookies ='1'
[Thu Feb 06 10:56:08.393290 2025] WeBWorK::Authen::set_params: params user='admin2' key='tEZJRZZ4OMvgNjUbZoChZmTcM7M8IDzu'
[Thu Feb 06 10:56:08.393397 2025] WeBWorK::Authen::verify: END VERIFY
[Thu Feb 06 10:56:08.393458 2025] WeBWorK::Authen::verify: result 1
[Thu Feb 06 10:56:08.393546 2025] (eval): Hi, admin2, glad you made it.
[Thu Feb 06 10:56:08.394553 2025] (eval): Now we deal with the effective user:
[Thu Feb 06 10:56:08.394667 2025] (eval): userID=admin2 eUserID=admin2
[Thu Feb 06 10:56:08.395214 2025] WeBWorK::ContentGenerator::ProblemSets::initialize: Begin collecting merged sets
[Thu Feb 06 10:56:08.397316 2025] WeBWorK::ContentGenerator::ProblemSets::initialize: Begin sorting merged sets
[Thu Feb 06 10:56:08.397560 2025] WeBWorK::ContentGenerator::ProblemSets::initialize: End preparing merged sets
[Thu Feb 06 10:56:08.429872 2025] WeBWorK::Authen::store_session: Saving database session. The database session contains
{
"key" => "tEZJRZZ4OMvgNjUbZoChZmTcM7M8IDzu",
"session" => {},
"timestamp" => 1738857368,
"user_id" => "admin2"
}
[Thu Feb 06 10:56:08.433834 2025] WeBWorK::Authen::store_session: The cookie session contains
{
"expiration" => 1800,
"key" => "tEZJRZZ4OMvgNjUbZoChZmTcM7M8IDzu",
"timestamp" => 1738857368,
"user_id" => "admin2"
}