ASR9K radius log

[nenadl]

Hi all,

I have a problem with ASR9k and radius server. My radius server is full of this messages:

4C3E4D4B464456 represent username, but I don't know where to find this on ASR.

4C3E4D4B464456	10.10.10.10	15.09.2015. 11:59:33	00h:24m:47s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:56:31	00h:27m:49s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:53:29	00h:30m:51s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:50:27	00h:33m:53s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:47:25	00h:36m:55s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:44:23	00h:39m:57s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:41:20	00h:43m:00s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:38:18	00h:46m:02s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:35:16	00h:49m:04s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:32:14	00h:52m:06s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:29:12	00h:55m:08s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:26:09	00h:58m:11s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:23:07	01h:01m:13s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:20:05	01h:04m:15s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:14:01	01h:10m:19s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:10:58	01h:13m:22s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:07:56	01h:16m:24s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:04:54	01h:19m:26s
4C3E4D4B464456	10.10.10.10	15.09.2015. 11:01:52	01h:22m:28s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:58:50	01h:25m:30s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:52:45	01h:31m:35s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:49:43	01h:34m:37s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:46:41	01h:37m:39s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:43:39	01h:40m:41s
4C3E4D4B464456	10.10.10.10	15.09.2015. 10:40:37	01h:43m:43s

Any help?

Regards,

Nenad

[Aleksandar Vidakovic]

Hi Nenad,

if these are subscribers for whom the authentication has failed, try this command:

RP/0/RSP0/CPU0:IM1#sh subscriber manager disconnect-history ?
  last    Display list of last disconnected sessions
  unique  Display list of unique disconnect history entries

Regards,

Aleksandar

[nenadl]

Hi Aleksandar,

there is no subscribers configuration on ASR.

RP/0/RSP0/CPU0:asr9k#sh subscriber manager disconnect-history last
Tue Sep 15 14:43:34.847 CEST

[ IEDGE DISCONNECT HISTORY LAST SESSIONS ]

 Location: 0/RSP0/CPU0

 Location: 0/0/CPU0

############################################################

RP/0/RSP0/CPU0:asr9k#sh subscriber manager disconnect-history unique
Tue Sep 15 14:43:38.610 CEST

[ IEDGE DISCONNECT HISTORY UNIQUE EVENTS ]

 Location: 0/RSP0/CPU0

 Location: 0/0/CPU0

###########################################################

RP/0/RSP0/CPU0:asr9k#sh subscriber session all
Tue Sep 15 14:44:17.218 CEST
Codes: IN - Initialize, CN - Connecting, CD - Connected, AC - Activated,
       ID - Idle, DN - Disconnecting, ED - End

Type         Interface                State     Subscriber IP Addr / Prefix                              
                                                LNS Address (Vrf)                              
-------------------------------------------------------------------------------

Regards/Pozdrav

Nenad

[xthuijs]

could it be that you are using radius for login authentication and that there is a mgmt station in use that uses that username to try and connect for shell access?

I converted that username to ascii but that doesnt make much sense either: "L>MKFDV"

you could use a :

RP/0/RSP0/CPU0:A9K-BNG#debug radius filter username <uname>

to get some records from the a9k and see when and why and for what it is reaching out to radius for.

show us also a show run | i aaa

cheers

xander

[nenadl]

Hi Alexander,

there is no mgmt station that uses that username to try to connect for shell access.

This is output from debug radius on asr:

RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Building header for the Authentication request
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Picking the rad id 210:1 sockfd 0x5004C188
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: rctx 0x501288b0 added successfully
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Reencoding NAS-IP prev 0.0.0.0 new 10.10.10.10
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: SMIAP Reencoding NAS-IP new 10.10.10.10 for vrf 0x60000006
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS: Send Access-Request to 192.168.101.30:1812 id 210, len 78
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  authenticator C0 49 03 71 62 8C B6 8B - 0C 11 27 3A B8 45 AA A7
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  User-Name           [1]     16      4C3E4D4B464456
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  User-Password       [2]     18      *       
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  Nas-Identifier      [32]    18      asr9k
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  NAS-IP-Address      [4]     6       10.10.10.10
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Updating last used server
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Got global deadtime 0
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Start timer thread rad_ident 210 remote_port 1812 remote_addr 0xc0a8651e, socket 1342488968 rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Successfully sent packet and started timeout handler for rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Building header for the Accounting request
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Picking the rad id 211:1 sockfd 0x5004C188
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: rctx 0x50127300 added successfully
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Reencoding NAS-IP prev 0.0.0.0 new 10.10.10.10
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: SMIAP Reencoding NAS-IP new 10.10.10.10 for vrf 0x60000006
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS: Send Accounting-Request to 192.168.101.30:1813 id 211, len 78
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  authenticator 87 A2 38 CC 1C A5 F6 19 - 61 DF 11 9B 1C 4E 64 5A
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  User-Name           [1]     16      4C3E4D4B464456
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  Acct-Status-Type    [40]    6       Start[0]
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  Event-Timestamp     [55]    6       1442382929
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  Nas-Identifier      [32]    18      asr9k
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  NAS-IP-Address      [4]     6       10.10.10.10
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  Acct-Delay-Time     [41]    6       0       
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Updating last used server
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Got global deadtime 0
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Start timer thread rad_ident 211 remote_port 1813 remote_addr 0xc0a8651e, socket 1342488968 rctx 0x50127300
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Successfully sent packet and started timeout handler for rctx 0x50127300
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: rctx found is 0x50127300
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS: Received from id 211 192.168.101.30:1813, Accounting-response, len 20
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]:  RADIUS:  authenticator 35 05 76 E5 88 2E 58 63 - 59 23 1D BC D8 D3 0E 2F
RP/0/RSP0/CPU0:Sep 16 07:55:29 : radiusd[1126]: Freeing server group transaction_id (1F000022)
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]: rctx found is 0x501288b0
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]:  RADIUS: Received from id 210 192.168.101.30:1812, Access-Reject, len 54
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]:  RADIUS:  authenticator 2E 24 89 F5 B7 7A 86 EC - D3 61 A5 E9 2C EA 6E B7
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]:  RADIUS:  Reply-Message       [18]    34      #SQL: Korisnik ne postoji u bazi
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]: Freeing server group transaction_id (BE000026)
RP/0/RSP0/CPU0:Sep 16 07:55:30 : radiusd[1126]: server 192.168.101.30/1812/1813 UP->UP

sh run aaa

radius-server host 192.168.101.30 auth-port 1812 acct-port 1813
 key 7 xxxxxxxxxxxxxxxxxxx
!
!
aaa accounting exec default start-stop group freeradius
aaa group server radius freeradius
 server 192.168.101.30 auth-port 1812 acct-port 1813
 vrf mng-core
 source-interface Loopback3
!
aaa authorization exec default group freeradius local
aaa authentication login CONSOLE line local
aaa authentication login default group freeradius local

Nenad

[xthuijs]

ok that helps.

you are getting this radius request induced by an exec connection attempt to the device via telnet.

so someone or something is trying to login with that funky username.

radius rejects that username since it claims it is not in the database.

next thing to check is who or what is (trying to) log(ging) in.

maybe you have some inband mgmt connection requests and you may want to use MPP to restrict access to exec to be received from only your mgmt networks to remediate this situation.

cheers

xander

[nenadl]

Problem is that I can't find who is trying to connect and from where, from which address.

At the moment I don't have MPP configured on ASR 0 and dont have inband connections or reverse telnet or something like that.. I only accept ssh connections on box from my addresses.

This is very strange situation, and start happened from the moment of installations router.
Is it possible to ASR generate some internal process for that?

This is normal output from debug radius, when user is in datebase:

RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received clinfop lwm_info - 50128004
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received a message type - 1 rctx 501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: [492] Received ASCII LOGIN/login from <unknown> with user=cisco, ifh=0x0, tty=/dev/vty1
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute User Name = cisco(13)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: method = server group map # 1001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rib lookup result found  1073735208
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Cannot get IP address, error: No error
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-IP-Address = 0.0.0.0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port-Type = 0 0 0 5 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Service-Type = Login
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Calling-Station-Id = 32 31 37 2e ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute User Password = *
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port = 131
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 1 15 0: 6e656e61
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 61 6 1: 5
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 6 6 1: 1
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 31 15 0: 3231372e
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Trying to find the first radius server to use.
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Created transaction_id (F000004A) for server group F000001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Picking the rad id 184:2 sockfd 0x5004C1A4
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx 0x501288b0 added successfully
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Reencoding NAS-IP prev 0.0.0.0 new 10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: SMIAP Reencoding NAS-IP new 10.10.10.10 for vrf 0x60000006
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Send Access-Request to 192.168.101.30:1812 id 184, len 92
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator 0F 00 00 01 A9 00 00 02 - A9 00 00 02 00 00 00 00
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  User-Name           [1]     15      cisco
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-IP-Address      [4]     6       10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port            [5]     6       131     
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port-Type       [61]    6       Virtual[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Service-Type        [6]     6       Login[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  User-Password       [2]     18      *       
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Updating last used server
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Calling-Station-Id  [31]    15      192.168.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Start timer thread rad_ident 184 remote_port 1812 remote_addr 0xc0a8651e, socket 1342488996 rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Successfully sent packet and started timeout handler for rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Got global deadtime 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx found is 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Received from id 184 192.168.101.30:1812, Access-Accept, len 57
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator 69 7E A2 A1 BE 8F 0F 52 - BE 31 31 0E 17 79 47 39
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Vendor,Cisco        [26]    25      
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:   Cisco AVpair        [1]    19      shell:priv-lvl=15
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Service-Type        [6]     6       NAS Prompt[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Idle-Timeout        [28]    6       1800    
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Freeing server group transaction_id (F000004A)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: VSA attr 26 25 -1: 9
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Choosing 'shell' proto for service login
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 6 6 1: 7
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Choosing 'shell' proto for service login
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 28 6 1: 708
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Choosing 'shell' proto for service login
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Bad attr (radius_net_author: unsupported): type=Idle-Timeout len=6
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: No appropriate authorization type for user
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Add last used server
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: pack_length = 57 radius_len = 57
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Add last used server = 192.168.101.30
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Sending sync reply (status PASS) to the client
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Dispatching message type 5
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received clinfop lwm_info - 50128004
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received a message type - 18 rctx 501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: [0] Received AUTHOR SHELL/exec from <unknown> with user=cisco, ifh=0x0, tty=/dev/vty1
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: method = server group map # 1001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rib lookup result found  1073735208
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Cannot get IP address, error: No error
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-IP-Address = 0.0.0.0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port = 131
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port-Type = 0 0 0 5 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Service-Type = EXEC
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute User Name = cisco(13)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Calling-Station-Id = 32 31 37 2e ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 1 15 0: 6e656e61
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 61 6 1: 5
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute User Password = *
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 6 6 1: 7
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 31 15 0: 3231372e
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Trying to find the first radius server to use.
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Created transaction_id (C2000044) for server group F000001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Picking the rad id 185:2 sockfd 0x5004C1A4
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx 0x501288b0 added successfully
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Reencoding NAS-IP prev 0.0.0.0 new 10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: SMIAP Reencoding NAS-IP new 10.10.10.10 for vrf 0x60000006
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Send Access-Request to 192.168.101.30:1812 id 185, len 92
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator 0F 00 00 01 A9 00 00 02 - A9 00 00 02 00 00 00 00
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  User-Name           [1]     15      cisco
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-IP-Address      [4]     6       10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port            [5]     6       131     
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port-Type       [61]    6       Virtual[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Service-Type        [6]     6       NAS Prompt[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Calling-Station-Id  [31]    15      192.168.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  User-Password       [2]     18      *       
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Got global deadtime 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Updating last used server
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Start timer thread rad_ident 185 remote_port 1812 remote_addr 0xc0a8651e, socket 1342488996 rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Successfully sent packet and started timeout handler for rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx found is 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Received from id 185 192.168.101.30:1812, Access-Accept, len 57
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Vendor,Cisco        [26]    25      
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:   Cisco AVpair        [1]    19      shell:priv-lvl=15
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Service-Type        [6]     6       NAS Prompt[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator E5 8A 8F F7 50 95 76 D5 - F0 E9 3A 3D 53 8A 4A 2E
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Idle-Timeout        [28]    6       1800    
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Freeing server group transaction_id (C2000044)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: pack_length = 57 radius_len = 57
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: VSA attr 26 25 -1: 9
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 6 6 1: 7
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 28 6 1: 708
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Add last used server
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Add last used server = 192.168.101.30
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Sending sync reply (status PASS) to the client
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Dispatching message type 7
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received clinfop lwm_info - 50128004
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Received a message type - 15 rctx 501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: method = server group map # 1001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: [0] Received ACCT START/exec from <unknown> with user=cisco, ifh=0x0, tty=/dev/vty1
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute User Name = cisco(13)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rib lookup result found  1073735208
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Cannot get IP address, error: No error
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port = 131
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-IP-Address = 0.0.0.0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute NAS-Port-Type = 0 0 0 5 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Acct-Status-Type = 0 0 0 1 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_METHODLIST_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_AUTHEN_METHOD_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_TTYNAME_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_REMOTE_ADDR_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_STARTTIME_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_ACCT_SESSID_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_TIMEZONE_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_TYPE_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_STARTTIME_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_TASKID_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translated attribute AAA_TASKID_ATTR to standard RADIUS attr Acct-Session-Id = 30 30 30 30 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_ACCT_DELAY_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translated attribute AAA_ACCT_DELAY_ATTR to standard RADIUS attr Acct-Delay-Time = 0 0 0 0 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_EVENT_TIMESTAMP_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translated attribute AAA_EVENT_TIMESTAMP_ATTR to standard RADIUS attr Acct-Event-Timestamp = 55 fffffff9 50 75 ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Service-Type = EXEC
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_LAST_METHOD_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Added standard attribute Calling-Station-Id = 32 31 37 2e ...
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 1 15 0: 6e656e61
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 61 6 1: 5
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 6 6 1: 7
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Translating attribute AAA_CURR_METHOD_PTR_ATTR
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 40 6 1: 1
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 41 6 1: 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 55 6 1: 55f95075
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 31 15 0: 3231372e
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Trying to find the first radius server to use.
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: IETF attr 44 10 0: 30303030
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Created transaction_id (2100003E) for server group F000001
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Picking the rad id 186:2 sockfd 0x5004C1A4
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx 0x501288b0 added successfully
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Reencoding NAS-IP prev 0.0.0.0 new 10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: SMIAP Reencoding NAS-IP new 10.10.10.10 for vrf 0x60000006
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Send Accounting-Request to 192.168.101.30:1813 id 186, len 102
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  User-Name           [1]     15      cisco
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator 82 41 21 01 31 80 0E 34 - FB E4 F4 C3 05 17 71 B6
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port            [5]     6       131     
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-IP-Address      [4]     6       10.10.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  NAS-Port-Type       [61]    6       Virtual[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Service-Type        [6]     6       NAS Prompt[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Acct-Status-Type    [40]    6       Start[0]
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Acct-Session-Id     [44]    10      000000aa
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Event-Timestamp     [55]    6       1442402421
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Acct-Delay-Time     [41]    6       0       
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Updating last used server
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Got global deadtime 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Start timer thread rad_ident 186 remote_port 1813 remote_addr 0xc0a8651e, socket 1342488996 rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Successfully sent packet and started timeout handler for rctx 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  Calling-Station-Id  [31]    15      192.168.10.10
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: rctx found is 0x501288b0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS: Received from id 186 192.168.101.30:1813, Accounting-response, len 20
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]:  RADIUS:  authenticator 97 82 21 9F AE CC B3 42 - 91 D3 65 B3 83 9F 1B 77
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Freeing server group transaction_id (2100003E)
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: pack_length = 20 radius_len = 20
RP/0/RSP0/CPU0:Sep 16 13:20:21 : radiusd[1126]: Sending sync reply (status PASS) to the client

Nenad

[xthuijs]

maybe the debug aaa authen/author give some more clue that could show where an originating request comes from.

maybe there is a console server connected to the console that induces some characters which spawns a bidirectional exec session (seen when the line on the console server doesnt have the no exec configured) whereby they both spit garbage causing these erroneous login messages.

I am suspecting console or some local service that induces this considering that the calling station ID and service type are both not set in these radius requests at hand.

if you dont have MPP configured, inband connections *are* possible, so we shouldnt exclude that either from the equation (however they would normally set calling station id and service-type which we dont have).

xander

[nenadl]

Debug authen/auth didn't show anuthing. Still nothing, someone still trying to connect on asr with that weird username every 3 min. I don't have nothing connected to console port on asr. Very strange situation...

Regards,

Nenad

[xthuijs]

yeah it is very fishy indeed nenad.

perhaps you can trigger on the event and do a quick :

show tcp brief | i ":23" | ex "0.0.0.0" this should give a list of tcp sockets that are in timed wait that maybe gives us the remote address.

also check the console, and see if there is something on teh console that spawns an exec and interacts witht he router prompt.

xander