Re: Looking for successful auth debug between cisco 1113 acs 4.2

jawill47ec · ‎10-06-2010

Hello,

Does anyone have a successful authentication debug using cisco 1113 acs 4.2 and Active Directory? I'm not having success in setting this up and would like to see what a successful authentication debug looks. Below is my current situation:

Oct 6 13:52:23: TPLUS: Queuing AAA Authentication request 444 for processing
Oct 6 13:52:23: TPLUS: processing authentication start request id 444
Oct 6 13:52:23: TPLUS: Authentication start packet created for 444()
Oct 6 13:52:23: TPLUS: Using server 110.34.5.143
Oct 6 13:52:23: TPLUS(000001BC)/0/NB_WAIT/46130160: Started 5 sec timeout
Oct 6 13:52:23: TPLUS(000001BC)/0/NB_WAIT: socket event 2
Oct 6 13:52:23: T+: Version 192 (0xC0), type 1, seq 1, encryption 1
Oct 6 13:52:23: T+: session_id 763084134 (0x2D7BBD66), dlen 26 (0x1A)
Oct 6 13:52:23: T+: type:AUTHEN/START, priv_lvl:15 action:LOGIN ascii
Oct 6 13:52:23: T+: svc:LOGIN user_len:0 port_len:6 (0x6) raddr_len:12 (0xC) data_len:0
Oct 6 13:52:23: T+: user:
Oct 6 13:52:23: T+: port: tty515
Oct 6 13:52:23: T+: rem_addr: 10.10.10.10
Oct 6 13:52:23: T+: data:
Oct 6 13:52:23: T+: End Packet
Oct 6 13:52:23: TPLUS(000001BC)/0/NB_WAIT: wrote entire 38 bytes request
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: Would block while reading
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: read entire 12 header bytes (expect 16bytes data)
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:23: TPLUS(000001BC)/0/READ: read entire 28 bytes response
Oct 6 13:52:23: T+: Version 192 (0xC0), type 1, seq 2, encryption 1
Oct 6 13:52:23: T+: session_id 763084134 (0x2D7BBD66), dlen 16 (0x10)
Oct 6 13:52:23: T+: AUTHEN/REPLY status:4 flags:0x0 msg_len:10, data_len:0
Oct 6 13:52:23: T+: msg: Username:
Oct 6 13:52:23: T+: data:
Oct 6 13:52:23: T+: End Packet
Oct 6 13:52:23: TPLUS(000001BC)/0/46130160: Processing the reply packet
Oct 6 13:52:23: TPLUS: Received authen response status GET_USER (7)
Oct 6 13:52:30: TPLUS: Queuing AAA Authentication request 444 for processing
Oct 6 13:52:30: TPLUS: processing authentication continue request id 444
Oct 6 13:52:30: TPLUS: Authentication continue packet generated for 444
Oct 6 13:52:30: TPLUS(000001BC)/0/WRITE/46130160: Started 5 sec timeout
Oct 6 13:52:30: T+: Version 192 (0xC0), type 1, seq 3, encryption 1
Oct 6 13:52:30: T+: session_id 763084134 (0x2D7BBD66), dlen 15 (0xF)
Oct 6 13:52:30: T+: AUTHEN/CONT msg_len:10 (0xA), data_len:0 (0x0) flags:0x0
Oct 6 13:52:30: T+: User msg: <elided>
Oct 6 13:52:30: T+: User data:
Oct 6 13:52:30: T+: End Packet
Oct 6 13:52:30: TPLUS(000001BC)/0/WRITE: wrote entire 27 bytes request
Oct 6 13:52:30: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:30: TPLUS(000001BC)/0/READ: read entire 12 header bytes (expect 16bytes data)
Oct 6 13:52:30: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:30: TPLUS(000001BC)/0/READ: read entire 28 bytes response
Oct 6 13:52:30: T+: Version 192 (0xC0), type 1, seq 4, encryption 1
Oct 6 13:52:30: T+: session_id 763084134 (0x2D7BBD66), dlen 16 (0x10)
Oct 6 13:52:30: T+: AUTHEN/REPLY status:5 flags:0x1 msg_len:10, data_len:0
Oct 6 13:52:30: T+: msg: Password:
Oct 6 13:52:30: T+: data:
Oct 6 13:52:30: T+: End Packet
Oct 6 13:52:30: TPLUS(000001BC)/0/46130160: Processing the reply packet
Oct 6 13:52:30: TPLUS: Received authen response status GET_PASSWORD (8)
Oct 6 13:52:37: TPLUS: Queuing AAA Authentication request 444 for processing
Oct 6 13:52:37: TPLUS: processing authentication continue request id 444
Oct 6 13:52:37: TPLUS: Authentication continue packet generated for 444
Oct 6 13:52:37: TPLUS(000001BC)/0/WRITE/46130160: Started 5 sec timeout
Oct 6 13:52:37: T+: Version 192 (0xC0), type 1, seq 5, encryption 1
Oct 6 13:52:37: T+: session_id 763084134 (0x2D7BBD66), dlen 16 (0x10)
Oct 6 13:52:37: T+: AUTHEN/CONT msg_len:11 (0xB), data_len:0 (0x0) flags:0x0
Oct 6 13:52:37: T+: User msg: <elided>
Oct 6 13:52:37: T+: User data:
Oct 6 13:52:37: T+: End Packet
Oct 6 13:52:37: TPLUS(000001BC)/0/WRITE: wrote entire 28 bytes request
Oct 6 13:52:37: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:37: TPLUS(000001BC)/0/READ: read entire 12 header bytes (expect 33bytes data)
Oct 6 13:52:37: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:37: TPLUS(000001BC)/0/READ: read entire 45 bytes response
Oct 6 13:52:37: T+: Version 192 (0xC0), type 1, seq 6, encryption 1
Oct 6 13:52:37: T+: session_id 763084134 (0x2D7BBD66), dlen 33 (0x21)
Oct 6 13:52:37: T+: AUTHEN/REPLY status:7 flags:0x0 msg_len:27, data_len:0
Oct 6 13:52:37: T+: msg: Error during authentication
Oct 6 13:52:37: T+: data:
Oct 6 13:52:37: T+: End Packet
Oct 6 13:52:37: TPLUS(000001BC)/0/46130160: Processing the reply packet
Oct 6 13:52:37: TPLUS: Received Authen status error
Oct 6 13:52:37: TPLUS(000001BC)/0/REQ_WAIT/46130160: timed out
Oct 6 13:52:37: TPLUS(000001BC)/0/REQ_WAIT/46130160: No sock_ctx found while handling request timeout
Oct 6 13:52:37: TPLUS: Choosing next server 101.34.5.143
Oct 6 13:52:37: TPLUS(000001BC)/1/NB_WAIT/46130160: Started 5 sec timeout
Oct 6 13:52:37: TPLUS(000001BC)/46130160: releasing old socket 0
Oct 6 13:52:37: TPLUS(000001BC)/1/46130160: Processing the reply packet
Oct 6 13:52:49: TPLUS: Queuing AAA Authentication request 444 for processing
Oct 6 13:52:49: TPLUS: processing authentication start request id 444
Oct 6 13:52:49: TPLUS: Authentication start packet created for 444()
Oct 6 13:52:49: TPLUS: Using server 172.24.5.143
Oct 6 13:52:49: TPLUS(000001BC)/0/NB_WAIT/46130160: Started 5 sec timeout
Oct 6 13:52:49: TPLUS(000001BC)/0/NB_WAIT: socket event 2
Oct 6 13:52:49: T+: Version 192 (0xC0), type 1, seq 1, encryption 1
Oct 6 13:52:49: T+: session_id 1523308383 (0x5ACBD75F), dlen 26 (0x1A)
Oct 6 13:52:49: T+: type:AUTHEN/START, priv_lvl:15 action:LOGIN ascii
Oct 6 13:52:49: T+: svc:LOGIN user_len:0 port_len:6 (0x6) raddr_len:12 (0xC) data_len:0
Oct 6 13:52:49: T+: user:
Oct 6 13:52:49: T+: port: tty515
Oct 6 13:52:49: T+: rem_addr: 10.10.10.10
Oct 6 13:52:49: T+: data:
Oct 6 13:52:49: T+: End Packet
Oct 6 13:52:49: TPLUS(000001BC)/0/NB_WAIT: wrote entire 38 bytes request
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: Would block while reading
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: read entire 12 header bytes (expect 43bytes data)
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: socket event 1
Oct 6 13:52:49: TPLUS(000001BC)/0/READ: read entire 55 bytes response
Oct 6 13:52:49: T+: Version 192 (0xC0), type 1, seq 2, encryption 1
Oct 6 13:52:49: T+: session_id 1523308383 (0x5ACBD75F), dlen 43 (0x2B)
Oct 6 13:52:49: T+: AUTHEN/REPLY status:4 flags:0x0 msg_len:37, data_len:0
Oct 6 13:52:49: T+: msg: 0x0A User Access Verification 0x0A 0x0A Username:
Oct 6 13:52:49: T+: data:
Oct 6 13:52:49: T+: End Packet
Oct 6 13:52:49: TPLUS(000001BC)/0/46130160: Processing the reply packet
Oct 6 13:52:49: TPLUS: Received authen response status GET_USER (7)

The 1113 acs failed reports shows:

External DB is not operational

thanks,

james

Vinay Sharma · ‎10-07-2010

Hi James,

We get External DB is not operational. Could you confirm if under External Databases > Unknown User Policy, and verify you have the AD/ Windows database at the top?

this error means the external server might not correctly configured on ACS external database section.

Another point is to make sure we have remote agent installed on supported windows server.

http://www.cisco.com/en/US/docs/net_mgmt/cisco_secure_access_control_server_for_solution_engine/4.2/installation/guide/remote_agent/rawi.html#wp289013

Also provide the Auth logs from the server running remote agent, e.g.:-

AUTH 10/25/2007 15:21:31 I 0376 1276 External DB [NTAuthenDLL.dll]:
Attempting Windows authentication for user v-michal
AUTH 10/25/2007 15:21:31 E 0376 1276 External DB [NTAuthenDLL.dll]: Windows
authentication FAILED (error 1783L)

thanks,

Vinay

Thanks & Regards

jawill47ec · ‎10-07-2010

Vinay,

Thanks for your reply. To provide additional info, the external database section I have configured is setup under Generic LDAP. I have configured the (2) LDAP servers as our primary/secondary AD Domain Controllers. I did not use the external database entitled "Windows Database".

The unknown user policy lists the name I created uner the Generic LDAP configuration. I called this Mycompany_Active_Directory. This is the name at the top of the selected databases.

I am not using the acs remote agents. Is it required to use the remote agents when using the Generic LDAP to authenticate against Active Directory Domain Controllers?

thanks for your help/time.

james

jedubois · ‎10-07-2010

James,

The Remote Agent is not requierd for Generic LDAP, if you are getting external DB not operational on your ACS for Generic LDAP then the connection or bind is most likely failing to your LDAP server. Please review your configuration on your ACS and make sure it has the correct setting to access your domain. If you are familar with the ACS logs you can turn the logging to Full under System Configuration -> Service control then view the Auth.log on your ACS for clues regarding the bind to the LDAP server. Also a packet capture may shed some light on the bind to AD.

One other note, if you are trying to use LDAPS to connect to AD try unencrypted LDAP first and see if that works for you, it will help narrow down the issue.

--Jesse

Looking for successful auth debug between cisco 1113 acs 4.2 and Active Directory