Re: failed to receive Accounting Response
Now I present fully situation on a trouble process (radiusd -X; cisco debug accounting; tcpdump vvv ports 1812-1814) On radius server firewall is absent, this is the open system. On cisco like this: access-list 1 permit 192.168.255.0 0.0.0.255 access-list 1 deny any 1) User connect to the cisco 1.1) radiusd -X rad_recv: Access-Request packet from host 192.168.255.10 port 1812, id=140, length=77 NAS-IP-Address = 192.168.255.10 NAS-Port = 2 NAS-Port-Type = Virtual User-Name = "userA" Calling-Station-Id = "192.168.255.116" User-Password = "passwA" +- entering group authorize {...} ++[preprocess] returns ok [suffix] No '@' in User-Name = "userA", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [files] users: Matched entry userA at line 7 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Found Auth-Type = PAP +- entering group PAP {...} [pap] login attempt with password "passwA" [pap] Using clear text password "passwA" [pap] User authenticated successfully ++[pap] returns ok Login OK: [userA/passwA] (from client csv port 2 cli 192.168.255.116) +- entering group post-auth {...} ++[exec] returns noop Sending Access-Accept of id 140 to 192.168.255.10 port 1812 Service-Type = NAS-Prompt-User Cisco-AVPair = "shell:priv-lvl=1" Finished request 6. Going to the next request Waking up in 4.9 seconds. rad_recv: Accounting-Request packet from host 192.168.255.10 port 1813, id=141, length=93 NAS-IP-Address = 192.168.255.10 NAS-Port = 2 NAS-Port-Type = Virtual User-Name = "userA" Calling-Station-Id = "192.168.255.116" Acct-Status-Type = Start Acct-Authentic = RADIUS Service-Type = NAS-Prompt-User Acct-Session-Id = "0000012B" Acct-Delay-Time = 0 +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 2,Client-IP-Address = 192.168.255.10,NAS-IP-Address = 192.168.255.10,Acct-Session-Id = "0000012B",User-Name = "userA"' [acct_unique] Acct-Unique-Session-ID = "76873ebbdef2d2d8". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "userA", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop ++[files] returns noop +- entering group accounting {...} [detail] expand: /var/log/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radacct/192.168.255.10/detail-20090308 [detail] /var/log/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radacct/192.168.255.10/detail-20090308 [detail] expand: %t -> Sun Mar 8 00:20:17 2009 ++[detail] returns ok rlm_counter: We only run on Accounting-Stop packets. ++[daily] returns noop [radutmp] expand: /var/log/radutmp -> /var/log/radutmp [radutmp] expand: %{User-Name} -> userA ++[radutmp] returns ok [sradutmp] expand: /var/log/sradutmp -> /var/log/sradutmp [sradutmp] expand: %{User-Name} -> userA ++[sradutmp] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> userA attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 141 to 192.168.255.10 port 1813 Finished request 7. Cleaning up request 7 ID 141 with timestamp +144 Going to the next request Waking up in 4.9 seconds. Cleaning up request 6 ID 140 with timestamp +144 Ready to process requests. 1.2) cisco debug log 002143: Mar 7 21:20:11: AAA: parse name=tty2 idb type=-1 tty=-1 002144: Mar 7 21:20:11: AAA: name=tty2 flags=0x11 type=5 shelf=0 slot=0 adapter=0 port=2 channel=0 002145: Mar 7 21:20:11: AAA/MEMORY: create_user (0x80D19744) user='' ruser='' port='tty2' rem_addr='192.168.255.116' authen_type=ASCII service=LOGIN priv=1 002146: Mar 7 21:20:19: tty2 AAA/AUTHOR/EXEC (4225439048): Port='tty2' list='' service=EXEC 002147: Mar 7 21:20:19: AAA/AUTHOR/EXEC: tty2 (4225439048) user='userA' 002148: Mar 7 21:20:19: tty2 AAA/AUTHOR/EXEC (4225439048): send AV service=shell 002149: Mar 7 21:20:19: tty2 AAA/AUTHOR/EXEC (4225439048): send AV cmd* 002150: Mar 7 21:20:19: tty2 AAA/AUTHOR/EXEC (4225439048): found list "default" 002151: Mar 7 21:20:19: tty2 AAA/AUTHOR/EXEC (4225439048): Method=radius (radius) 002152: Mar 7 21:20:19: AAA/AUTHOR (4225439048): Post authorization status = PASS_ADD 002153: Mar 7 21:20:19: AAA/AUTHOR/EXEC: Processing AV service=shell 002154: Mar 7 21:20:19: AAA/AUTHOR/EXEC: Processing AV cmd* 002155: Mar 7 21:20:19: AAA/AUTHOR/EXEC: Processing AV priv-lvl=1 1.3) tcpdump 00:20:17.595207 IP (tos 0x0, ttl 255, id 39695, offset 0, flags [none], proto UDP (17), length 105) 192.168.255.10.1812 > 192.168.255.2.1812: RADIUS, length: 77 Access Request (1), id: 0x8c, Authenticator: 61af38df3d49196d536ade8e46774faa NAS IP Address Attribute (4), length: 6, Value: 192.168.255.10 0x0000: c0a8 ff0a NAS Port Attribute (5), length: 6, Value: 2 0x0000: 0000 0002 NAS Port Type Attribute (61), length: 6, Value: Virtual 0x0000: 0000 0005 Username Attribute (1), length: 4, Value: userA 0x0000: 7532 Calling Station Attribute (31), length: 17, Value: [|radius] 0x0000: 3139 322e 3136 382e 3235 [|radius] 00:20:17.595632 IP (tos 0x0, ttl 64, id 40797, offset 0, flags [none], proto UDP (17), length 78) 192.168.255.2.1812 > 192.168.255.10.1812: [bad udp cksum 5a95!] RADIUS, length: 50 Access Accept (2), id: 0x8c, Authenticator: 32d46241a0413e2a2970fff9fbf1a010 Service Type Attribute (6), length: 6, Value: NAS Prompt 0x0000: 0000 0007 Vendor Specific Attribute (26), length: 24, Value: Vendor: Cisco (9) Vendor Attribute: 1, Length: 16, Value: shell:priv-lvl=1 0x0000: 0000 0009 0112 7368 656c 6c3a 7072 6976 0x0010: 2d6c 766c 3d31 00:20:17.613428 IP (tos 0x0, ttl 255, id 39697, offset 0, flags [none], proto UDP (17), length 121) 192.168.255.10.1813 > 192.168.255.2.1813: RADIUS, length: 93 Accounting Request (4), id: 0x8d, Authenticator: 78efee9d88e11dcafaaf188213873e56 NAS IP Address Attribute (4), length: 6, Value: 192.168.255.10 0x0000: c0a8 ff0a NAS Port Attribute (5), length: 6, Value: 2 0x0000: 0000 0002 NAS Port Type Attribute (61), length: 6, Value: Virtual 0x0000: 0000 0005 Username Attribute (1), length: 4, Value: userA 0x0000: 7532 Calling Station Attribute (31), length: 17, Value: [|radius] 0x0000: 3139 322e 3136 382e 3235 [|radius] 00:20:17.614190 IP (tos 0x0, ttl 64, id 40799, offset 0, flags [none], proto UDP (17), length 48) 192.168.255.2.1813 > 192.168.255.10.1813: [bad udp cksum 7518!] RADIUS, length: 20 Accounting Response (5), id: 0x8d, Authenticator: 59edaa59beed3b78b57a3e4c9b6146b5 2.) User run some command 2.1) radiusd -X (nothing) 2.2) cisco debug 002156: Mar 7 21:22:59: AAA/ACCT/CMD: User userA, Port tty2, Priv 1: "ping 192.168.101.147 <cr>" 002157: Mar 7 21:22:59: AAA/ACCT/CMD: Found list "default" 002158: Mar 7 21:22:59: AAA/ACCT: user userA, acct type 3 (2103679520): Method=radius (radius) 2.3) tcpdump (nothing) 3) User logoff from cisco 3.1) radiusd -X rad_recv: Accounting-Request packet from host 192.168.255.10 port 1813, id=142, length=105 NAS-IP-Address = 192.168.255.10 NAS-Port = 2 NAS-Port-Type = Virtual User-Name = "userA" Calling-Station-Id = "192.168.255.116" Acct-Status-Type = Stop Acct-Authentic = RADIUS Service-Type = NAS-Prompt-User Acct-Session-Id = "0000012B" Acct-Terminate-Cause = User-Request Acct-Session-Time = 286 Acct-Delay-Time = 0 +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 2,Client-IP-Address = 192.168.255.10,NAS-IP-Address = 192.168.255.10,Acct-Session-Id = "0000012B",User-Name = "userA"' [acct_unique] Acct-Unique-Session-ID = "76873ebbdef2d2d8". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "userA", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop ++[files] returns noop +- entering group accounting {...} [detail] expand: /var/log/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radacct/192.168.255.10/detail-20090308 [detail] /var/log/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radacct/192.168.255.10/detail-20090308 [detail] expand: %t -> Sun Mar 8 00:25:03 2009 ++[detail] returns ok rlm_counter: Packet Unique ID = '76873ebbdef2d2d8' rlm_counter: This Service-Type is not allowed. Returning NOOP. ++[daily] returns noop [radutmp] expand: /var/log/radutmp -> /var/log/radutmp [radutmp] expand: %{User-Name} -> userA ++[radutmp] returns ok [sradutmp] expand: /var/log/sradutmp -> /var/log/sradutmp [sradutmp] expand: %{User-Name} -> userA ++[sradutmp] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> userA attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 142 to 192.168.255.10 port 1813 Finished request 8. Cleaning up request 8 ID 142 with timestamp +430 Going to the next request Ready to process requests. 3.2) cisco debug 002159: Mar 7 21:25:05: AAA/ACCT/ACCT_DISC: Found list "default" 002160: Mar 7 21:25:05: tty2 AAA/DISC: 1/"User Request" 002161: Mar 7 21:25:05: AAA/ACCT/ACCT_DISC: Found list "default" 002162: Mar 7 21:25:05: tty2 AAA/DISC/EXT: 1020/"User Request" 002163: Mar 7 21:25:05: AAA/ACCT/ACCT_DISC: Found list "default" 002164: Mar 7 21:25:05: tty2 AAA/DISC: 9/"NAS Error" 002165: Mar 7 21:25:05: AAA/ACCT/ACCT_DISC: Found list "default" 002166: Mar 7 21:25:05: tty2 AAA/DISC/EXT: 1002/"Unknown" 002167: Mar 7 21:25:05: AAA/ACCT: no attribute "elapsed_time" to replace, adding it 002168: Mar 7 21:25:05: AAA/ACCT/EXEC/STOP: cannot retrieve modem speed 3.3) tcpdump 00:25:03.354629 IP (tos 0x0, ttl 255, id 40103, offset 0, flags [none], proto UDP (17), length 133) 192.168.255.10.1813 > 192.168.255.2.1813: RADIUS, length: 105 Accounting Request (4), id: 0x8e, Authenticator: 7e7d0e10eedbb36b1c4576db6cb7ed55 NAS IP Address Attribute (4), length: 6, Value: 192.168.255.10 0x0000: c0a8 ff0a NAS Port Attribute (5), length: 6, Value: 2 0x0000: 0000 0002 NAS Port Type Attribute (61), length: 6, Value: Virtual 0x0000: 0000 0005 Username Attribute (1), length: 4, Value: userA 0x0000: 7532 Calling Station Attribute (31), length: 17, Value: [|radius] 0x0000: 3139 322e 3136 382e 3235 [|radius] 00:25:03.355476 IP (tos 0x0, ttl 64, id 40963, offset 0, flags [none], proto UDP (17), length 48) 192.168.255.2.1813 > 192.168.255.10.1813: [bad udp cksum a2ee!] RADIUS, length: 20 Accounting Response (5), id: 0x8e, Authenticator: e433717ece1d6709b80331d05e7d2b31 PS:Sorry for my bad english and thanks for a privious answers!
Now I present fully situation on a trouble process
I don't see a problem.
1) User connect to the cisco
1.1) radiusd -X
Authentication works, accounting Start works.
2.) User run some command
2.1) radiusd -X
(nothing)
Of course. Radius doesn't do command accounting. That's TACACS.
3) User logoff from cisco
3.1) radiusd -X
Accounting Stop works. Ivan Kalik Kalik Informatika ISP
participants (2)
-
"Николай Г. Петров" -
tnt@kalik.net