Security

CPPM 6.8.3

I have social login setup through Google. When I press the Google button on the login page it attempts the login and it fails in CPPM. I receive the below error in the logs. 

I also see this under Alerts. I receive similar errors if I switch to CHAP.

PAP:Clear text password check failed.

CHAP auth output:

CHAP: Wrong user password

Regular guest/self-reg workflows function as expected. My endpoint is updated with the social login attributes as well.

I even ran the query from the Social Login Authentication source against the live DB, and I receive results. I just can't make the password match for whatever reason. I also tried this incognito to force me through the whole Google auth process again incase it had an old password cached somehwere. I'm sure I am overlooking a checkbox somewhere.

I've had this working before, so I'm not sure what's going on here. Seemingly stopped after the upgrade to 6.8.0 -> 6.8.3, but I may be mistaken on the timeline.

2019-11-24 17:11:38,953	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] INFO RadiusServer.Radius - rlm_sql: searching for user z*******@gmail.com in Local:localhost
2019-11-24 17:11:38,955	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] ERROR RadiusServer.Radius - rlm_sql (authsrc_10): Error parsing data from database
2019-11-24 17:11:38,955	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] ERROR RadiusServer.Radius - rlm_sql (authsrc_10): SQL query error; rejecting user
2019-11-24 17:11:38,955	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] INFO RadiusServer.Radius - rlm_sql: searching for user z*****@gmail.com in Local:localhost
2019-11-24 17:11:38,957	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] INFO RadiusServer.Radius - rlm_sql: found user z*******@gmail.com in Local:localhost
2019-11-24 17:11:38,957	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] INFO RadiusServer.Radius - SQL User lookup time = 2 ms
2019-11-24 17:11:38,957	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] INFO RadiusServer.Radius - rlm_pap: authenticating User z******@gmail.com
2019-11-24 17:11:38,957	[Th 41 Req 64204 SessId R00000398-01-5ddb0e2a] ERROR RadiusServer.Radius - rlm_pap: User z******@gmail.com authentication failed

I just tried in my lab with Google Social login both with a WebAuth and a Wireless Guest redirect using no pre-auth check and PAP against the Social Login Repository and it works all fine. What worries me is the 'SQL query error' in your logs.

For my successful authentication that part looks like:

2019-11-25 09:48:21,572	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - rlm_sql: searching for user h***@gmail.com in Local:localhost
2019-11-25 09:48:21,578	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - rlm_sql: searching for user h***@gmail.com in Local:localhost
2019-11-25 09:48:21,593	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - rlm_sql: found user h***@gmail.com in Local:localhost
2019-11-25 09:48:21,593	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - SQL User lookup time = 15 ms
2019-11-25 09:48:21,593	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - rlm_pap: authenticating User h***@gmail.com
2019-11-25 09:48:21,593	[Th 44 Req 141802 SessId R00001a19-13-5ddb9555] INFO RadiusServer.Radius - rlm_pap: User h***@gmail.com authenticated succesfully

If I check the query for the Social Login Repository, it uses '%{Connection:Client-Mac-Address-NoDelim}' as attribute in the query. Do you see that attribute filled in the access tracker?

Are you actually using an accesspoint/controller with redirect? That is needed to get the MAC address filled correctly. And did you whitelist google.com to make the authentication happen? As you mention the social attributes do get in the endpoint, that probably is the case, but just asking. Can you capture the username and password (for example with developer tools in your browser) to check if it actually matches against what is stored in the Social Login Database? If you have an 'old' entry, and the social logon does not update for some reason, the authentication will fail. The password in the Social Login Database should be updated on each social login and is effectively 'one-time use'.

If you still can't get this working, I would open a support case. As mentioned it works for me with 6.8.3. One difference may be that I just configured it, instead of upgrading the config from a previous version.

That was my thinking. PAP should be fine as I don't recall ever changing that on the controller previously. 

Can you paste your filter query from the [Social Login Repository] authentication source for the Authentication filter? I'm wondering if that is correct.

I can run that query against the live DB and I get the proper endpoint. So, I don't think that is the issue.

To answer your questions:

1. Yes, that attribute is populated. Otherwise, it wouldn't even find the user. Which in the logs, you can tell that it does.

2. Whitelist is good. I don't think that OAuth would ever complete otherwise.

3. I will check with dev tools to see if the password is the same. I do see that the endpoint is updated with A password using the Guest application log. I also see it in the raw logs.

Thanks

Here is the filter from my ClearPass:

1. SELECT te.attributes->>'social_password' AS User_Password FROM tips_endpoints as te WHERE te.mac_address = LOWER('%{Connection:Client-Mac-Address-NoDelim}') and jsonb_exists_all(te.attributes, '{social_password}')
2. SELECT te.attributes->>'social_method' AS SP FROM tips_endpoints as te WHERE te.mac_address = LOWER('%{Connection:Client-Mac-Address-NoDelim}') and jsonb_exists_all(te.attributes, '{social_method}')

And a screenshot of the full configuration of the Social Login Repository, which I think is factory default on my system:

So, I verified that the right password is being sent over to the controller. However I see a timeout in the logs on the controller:

Nov 25 09:05:46  authmgr[3783]: <520002> <3783> <ERRS> |authmgr|  Authentication server request Timeout, username=z*****@gmail.com userip=172.16.0.13 usermac=2c:6f:c9:5c:e9:a4 servername= Clearpass-DATA server-group=guest-preauth_cppm_sg serverip= 172.16.1.3 bssid=00:00:00:00:00:00 apname=Office
Nov 25 09:05:46  authmgr[3783]: <522275> <3783> <WARN> |authmgr|  User Authentication failed. username=z*****@gmail.com userip=172.16.0.13 usermac=2c:6f:c9:5c:e9:a4 authmethod=Web servername=Clearpass-DATA serverip=172.16.1.3 apname=Office bssid=00:00:00:00:00:00

Which doesn't make a lot of sense to me. If there was a problem with comms, then regular guest login shouldn't work, correct?

I agree it doesn't make sense. Can you share what is in Access Tracker for that request? Did it select the Social User store as authentication source? What is in the 'Alert' tab? There should be more than just the PAP cleartext password error.

If you prefer not to share that logs on this public forum, please work with Aruba Support, as they can interactively troubleshoot much more effective.

Alerts Tab:

Error Code:	
216
Error Category:	
Authentication failure
Error Message:	
User authentication failed
 Alerts for this Request 
RADIUS	
PAP: CLEAR TEXT password check failed

Access Tracker Auth Window:

Service:	
HomeNet - Cloud Identity - Social Media Authentication
Authentication Method:   PAP
Authentication Source:	Local:localhost
Authorization Source:	[Endpoints Repository], [Social Login Repository]
Roles:	[Employee], google
Enforcement Profiles:	[Deny Access Profile]
Service Monitor Mode:	
Disabled
Online Status:	
Not Available

Here are the DEBUG logs from the Access Tracker.

2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "HomeNet - Cloud Identity - Social Media Authentication"
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x00e2006e00cb00d4c2130100087bbae5b5448b9f59a712624f9aff2c, Session-Id = "R000003b8-01-5ddbee53"
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 70594
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 70594
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - Found Autz-Type svc_HomeNet - Cloud Identity - Social Media Authentication_3146
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: entering group svc_HomeNet - Cloud Identity - Social Media Authentication_3146 for request 70594
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: entering group for request 70594
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - rlm_sql: searching for user z******@gmail.com in Local:localhost
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - radius_xlat: Running registered xlat function of module Connection for string 'Client-Mac-Address-NoDelim'
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - radius_xlat: 'SELECT te.attributes->>'social_method' AS SP FROM tips_endpoints as te WHERE te.mac_address = LOWER('2C6FC95CE9A4') and jsonb_exists_all(te.attributes, '{social_method}')'
2019-11-25 09:08:03,501	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql (authsrc_10): Reserving sql socket id: 31
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql: The number of fields: 1.
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql: Coulmn label sp
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] ERROR RadiusServer.Radius - rlm_sql (authsrc_10): Error parsing data from database
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] ERROR RadiusServer.Radius - rlm_sql (authsrc_10): SQL query error; rejecting user
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql (authsrc_10): Released sql socket id: 31
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_10" returns fail for request 70594
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - rlm_sql: searching for user z*****@gmail.com in Local:localhost
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - radius_xlat: Running registered xlat function of module Connection for string 'Client-Mac-Address-NoDelim'
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - radius_xlat: 'SELECT mac_address AS User_Password FROM tips_endpoints WHERE mac_address = LOWER('2C6FC95CE9A4') AND status = 'Known''
2019-11-25 09:08:03,502	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql (authsrc_4): Reserving sql socket id: 31
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql: The number of fields: 1.
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql: Coulmn label user_password
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql (authsrc_4): User z*****@gmail.com found
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql (authsrc_4): Released sql socket id: 31
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - rlm_sql: found user z******@gmail.com in Local:localhost
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_sql: Adding Persisted-User-Name z*****@gmail.com to persistent items
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.Clearpass01.radius.auth._Endpoints_Repository_.lookup-time:1|ms
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.Clearpass01.radius.auth._Endpoints_Repository_.lookup-time:1|ms
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - SQL User lookup time = 1 ms
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.Clearpass01.radius.auth.time:1|ms
2019-11-25 09:08:03,503	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.Clearpass01.radius.auth.time:1|ms
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_4" returns ok for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3146_authmthd_2" returns noop for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3146_authmthd_6" returns noop for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_pap: Login attempt by "z*****@gmail.com". Setting Auth-Type to "svc_3146_authmthd_1".
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3146_authmthd_1" returns ok for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3146_authmthd_2, svc_3146_authmthd_6, svc_3146_authmthd_1
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - radius: No MS Identity VP
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3146_authmthd_1 set.
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3146_auth_check" returns ok for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: leaving group svc_HomeNet - Cloud Identity - Social Media Authentication_3146 (returns ok) for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3146_authmthd_1
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - auth: type "svc_3146_authmthd_1"
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: entering group svc_3146_authmthd_1 for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] INFO RadiusServer.Radius - rlm_pap: authenticating User z*****@gmail.com
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - rlm_pap: Using clear text password.
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] ERROR RadiusServer.Radius - rlm_pap: User z******@gmail.com authentication failed
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3146_authmthd_1" returns reject for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: leaving group svc_3146_authmthd_1 (returns reject) for request 70594
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - auth: Failed to validate the user.
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - Found Post-Auth-Type
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - Processing the post-auth section of radiusd.conf
2019-11-25 09:08:03,504	[Th 88 Req 70594 SessId R000003b8-01-5ddbee53] DEBUG RadiusServer.Radius - modcall: entering group REJECT for request 70594

So, from what I can tell, it finds the "social_method", username, and "User_Password" from the query, but it dies when it "compares" it to the one returned from oAuth?

Auth source in the service is set to Social and Endpoint repositories.

Guest Application log for Oauth:

Client:    172.16.0.13:50819
Script:    /guest/guestReg_login.php
Function:  OnPageExecute
Arguments: array (
  'mac_address' => '2c6fc95ce9a4',
  'social_method' => 'google',
  'social_username' => 'z*****@gmail.com',
  'social_password' => 'wDafBF6fpBwMwONm/r*****************',
  'social_timestamp' => 1574694477,
  'social_vip' => false,
  'social_args' => '{"page_name":"guestReg"}',
  'social_json' => '{"id":"107504947******","email":"z*****@gmail.com","verified_email":true,"name":"Z*** *******","given_name":"Z****","family_name":"E******","picture":"https:\/\/lh3.googleusercontent.com\/a-\/AAuE7mCpU9dgt8VCPWf2lC0kfjTkw*************","locale":"en"}',
)
Details:   array (
  'error' => 0,
)

 
Do you think this could have anything to do with 2FA that is enabled on my Google account? It shouldn't, but I'm beating my head against a wall at this point. 

Please work with Aruba Support as most things look to go right, up to the point where the actual password is verified. In my lab that just works.

What happens with Social Login is that after the OAuth (or SAML), a temporarily/one-time user account (random password) is created which can be used for a PAP (or other password) authentication through the captive portal. That is because with OAuth the might not be a password, or at least ClearPass doesn't have access to it.

Could it be that you have a ClearPass cluster, and do the captive portal authentication on a subscriber? If you do, you should add a delay in the authentication (5 seconds should be good) for the Social temporarily account to be synced to the subscriber.

So, 
I gave up on this for a while and then I came back to it. Somehow I had swapped the filter rules around. They were backwards. 1 was 2, 2 was 1. I didn't notice until I looked closely at your screenshot. No earthly clue why that happened. Don't beer and Clearpass I guess.  

Thanks for the assist!