Forum OpenACS Development: Login fails only to new users

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

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

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

Does user login work if password is reset?

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.

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?

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,

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,