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