Forum OpenACS Development: Login fails only to new users

Request notifications

Collapse
Posted by Iuri Sampaio on
Hi there,

I've noticed the login process fails only to new users on my oacs system. I suspect that happens because I'm using a customized registration form.

I've tracked the whole process down, the code execution from the very beginning, at ad_proc "auth::authenticate"
...
array set auth [auth::authenticate -email $username \
-password $password]

api-doc/proc-view?proc=auth%3a%3aauthenticate&source_p=1

to the deepest end, at "ad_proc -public acs_sc::invoke" and lastly "ad_proc -public ad_apply" (the very last one, i guess!).

/api-doc/proc-view?proc=acs_sc%3a%3ainvoke&source_p=1

/api-doc/proc-view?source_p=1&proc=ad_apply&version_id=
...
} {
set func_and_args [concat $func $arglist]
return [uplevel $func_and_args]
}

But I found nothing wrong, meaning no deprecated functions, nor unassigned and empty values . Plus, error.log shows the very same logs on both scenarios: 1. successful login and 2. failed attempt to login.

Furthermore, there's no difference in the registration scripts. I've copied the whole from acs-subsite/lib/user-new.tcl to the new form.

What could I be missing in the investigation, debugging the code?
Logs are below.

1. Failed to login
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: Running evex::ws::auth *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: Running ad_proc auth::authenticate *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: USERID 16716 *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: USERNMAE mailto:iuri@iiziurix.com ******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: Running ad_proc auth::authentication::Authenticate
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local GetParameters
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.getparameters.local *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: REST
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: OLD VERSION -1 *********
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ELSE mailto:iuri@iiziurix.com test 5 501 *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local Authenticate
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.authenticate.local mailto:iuri@iiziurix.com test {} 5 *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: REST auth_status bad_password auth_message {Nome ou senha inválidos}
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: RRRRRRR auth_status bad_password auth_message {Nome ou senha inválidos}
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local Authenticate
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.authenticate.local mailto:iuri@iiziurix.com test {} 5 *******
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: REST auth_status bad_password auth_message {Nome ou senha inválidos}
[30/Nov/2017:00:45:15][7582.7f0162ffd700][-conn:evex:9-] Notice: AIGH! something bad happened! Nome ou senha inválidos

2. Failure to login

[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: Running evex::ws::auth *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: Running ad_proc auth::authenticate *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: USERID 698 *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: USERNMAE iuri ******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: Running ad_proc auth::authentication::Authenticate
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local GetParameters
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.getparameters.local *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: REST
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: OLD VERSION -1 *********
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ELSE iuri jacare 5 501 *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local Authenticate
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.authenticate.local iuri 098764321 {} 5 *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: REST account_status ok auth_status ok
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: RRRRRRR account_status ok auth_status ok
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ************* auth_authentication local Authenticate
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: ACSSC AcsSc.auth_authentication.authenticate.local iuri jacare {} 5 *******
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: REST account_status ok auth_status ok
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: AUTH ok
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: YSEDI 698
[30/Nov/2017:00:45:19][7582.7f0162ffd700][-conn:evex:9-] Notice: im_generate_auto_login: expiry_date=, user_id=698

Collapse
Posted by Iuri Sampaio on
The logs are wrongly numbered:
1. failed attempt to login and
2. successful login
Collapse
Posted by Antonio Pisano on
Hi Iuri,

are the stars I see the obscured password? Are you sure the proper password makes it until the authentication? I am thinking about some encoding or other kind of corruption incident.

BTW, im_generate_auto_login makes me think about project-open. Which "vanilla authentication" was your starting boilerplate? Probably not the plain openacs one, right?

Ciao

Collapse
Posted by Iuri Sampaio on
Hi Antonio,

No, the asterisks (i.e. stars ****), they're just plain text to make log messages more visible in the crowd!

Passwords remain the very same until auth::authentication is completed. I confirmed that password hasn't been modified through all internal ad_procs by writing "ns_log Notices" (i.e. From auth::authenticate, auth::authenticate::Authenticate, ... , acs_sc::invoke to auth::authenticate)

While I was debugging, I had the same suspects of corruption that you had. Thus, I've set a very simple password (i.e. test and 098764321) and wrote ns_log notice along all the way through ad_procs.

Indeed, I'm im_generate_auto_login, but it's called only after auth::authentication proc has been completed. Meaning, authentication process is plain OpenACS.

Best wishes,

Collapse
Posted by Benjamin Brink on
Hi Iuri,

What defines a "new user"?
A user that has not registered?
A registered user that has no login history with browser being used?
A user that just registered and has not had to login yet?
something else?

Thanks,
Ben

Collapse
Posted by Benjamin Brink on
Oh, I get it now. Users that have recently registered in the custom registration form.. Okay.. Hmm..
Collapse
Posted by Benjamin Brink on
Does user login work if password is reset?
Collapse
Posted by Benjamin Brink on
Are there any duplicate emails in the parties table? That is, duplicate emails with different user_id?
Theoretically, party::get_by_email might return a different user_id than the expected one if there are duplicates associated with different accounts.
Collapse
Posted by Iuri Sampaio on
Hi Ben,

That's not the case. Even because I'm testing the login right after I'd added the user.

I've checked parties table, and confirm there's only one party. Plus, if I test the ad_proc aside my code context. (i.e. going to Shell and running party::get_by_email), it returns the proper party_id.

16548 | |
16712 | mailto:iuri.sampaio@gmail.com |
16714 | mailto:iuri@ibiziurix.com |
16716 | mailto:iuri@iiziurix.com |

How would I go further on debugging ad_proc ad_apply? The deny of authentication comes from its execution.

[01/Dec/2017:18:31:32][1940.7fb24a8ce700][-conn:evex:1-] Notice: REST auth_status bad_password auth_message {Nome ou senha inválidos}

What's even more strange is the ambiguous behavior, it works for old users, but doesn't to new ones.

Collapse
Posted by Benjamin Brink on
Hi Iuri,

Does login work when user password is reset?

If answer is yes, then registration is garbling the password..

Are new users able to login any other way?

Collapse
Posted by Iuri Sampaio on
Hi Ben,
Your idea brought positive results!

I tried to log in using login's webpage and the password was invalid. https://evex.co/register/user-new

Then, after resetting password, I was able to log in. However, API REST still returns "bad password"

user: mailto:iuri.sampaio@gmail.com
password: test

Failed to login.
http://evex.co/REST/userLoginRequest?username=iuri.sampaio@gmail.com&password=test&token=%22Please!%22

It seems acs-authentication denies any attempt from the custom package. Even though, the custom package as the same scripts and error.log shows the very same variables passing through the ad_procs. $auth_id, $impl_id and etc.

p.s. Old users (i.e. users registered using /acs-subsite/lib/user-new ) are able to login on both methods webpage and API REST

How would I debug ad_apply to find out where the new registration is garbling the password?

Collapse
Posted by Benjamin Brink on
Hi Iuri,
One way, is to step through the relevant code, adding ns_logs to log relevant values. This way,, when you make a test case, you can see where the value changes unexpectedly.

Maybe start where you know relevant values are accurate, and log at the last place just before values are stored. Then log at half points in between until you identify the offending code.
cheers,
Ben

Collapse
Posted by Iuri Sampaio on
That's done already. I've opened this thread precisely because of that. I've debugged all the way down, or should I say into ad_procs. I've added logs to all passages though them. At all log messages, username and password haven't changed so far, nothing is garbling pwd.

I've stopped at ad_apply, which I believe is the end point of debugging. In fact, I got stuck ad_apply because the code is very short and I believe there's no chance to the error be within deeper core ad_procs, is there?

https://openacs.org/api-doc/proc-view?proc=ad_apply&source_p=1

Either way, I need to burn more neurons on this task.

Best wishes,

Collapse
Posted by Brian Fenton on
Hi Iuri

I can assure that ad_apply is not the source of the problem. You say that you have a customised login page. Why not start with the "standard" OpenACS page that you know is working correctly, and then carefully add each change until you identify the problem?

Brian

Collapse
Posted by Iuri Sampaio on
Hi Brian,

"I can assure that ad_apply is not the source of the problem". So can I!

Finally, I've started from scratch and found the problem. MainSite parameter "RegistrationProvidesRandomPasswordP" was enabled. Because of it, the system generates a random password, even if we explicitly had passed the password and confirm_password fields, as API methods arguments/switches.

Testing things out a while ago, I should have enabled and I forgot to disable it later on.

The good thing...?! It was a good case as lesson learned to get knowing the whole registration and login adn their ad_procs workflow through pkgs: from acs-subsite, acs-authentication, acs-service-contract, acs-tcl ...

Best wishes,