failed to receive Accounting Response
"Николай Г. Петров"
bsdrab at gmail.com
Sat Mar 7 22:47:37 CET 2009
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!
More information about the Freeradius-Users
mailing list