Freeradius doesn't accept CoA-ACK or CoA-NAK.

26 Mar 2010

      Hi, Freeradius-users.

I have configured Freeradius 2.1.8 to check online users in blocked
table. On accept accounting request, freeradius asks a mysql table
"blocked" for a login. If TRUE, freeradius server send CoA packet to disconnect
PPPoE session.

Freeradius server sends CoA packet to NAS, PPPoE session is droped and NAS
send CoA-ACK, that pppoe session was droped. But freeradius doesn't
recognize CoA-ACK and try more send CoA packet to NAS.
NAS replys CoA-NAK, but freeradius doesn't recognize it too, and make
3-4 attempts to send CoA packet to NAS.

Configs:

iptv:~ # grep -v '#' /etc/raddb/sites-enabled/default
....
accounting {
        detail
        unix
        radutmp
        sql
        attr_filter.accounting_response
        if ("%{Acct-Status-Type}" != "Stop") {
                if ("%{sql: SELECT username from blocked where username = '%{User-Name}'}") {
                        update coa {
                                User-Name = "%{User-Name}"
                                Cisco-Account-Info = "S%{Framed-IP-Address}"
                                Cisco-AVPair = "subscriber:command=account-logoff"
                        }
                }
        }
}
....

iptv:~ # grep -v '#' /etc/raddb/sites-enabled/cisco7206
home_server cisco7206 {
        type = coa
        ipaddr = xx.xx.64.94
        port = 1700
        secret = xxxx
        retry_count = 1
        coa {
                irt = 1
                mrt = 1
                mrc = 10
                mrd = 5
        }
}
home_server_pool coa {
        type = fail-over

        home_server = cisco7206

}

iptv:~ # grep -v '#' /etc/raddb/clients.conf
client xx.xx.64.94 {
        secret = xxxxx
        nastype = cisco
        coa_server = cisco7206
}

*****************************************

Debug:

Sending CoA-Request of id 10 to xx.xx.64.94 port 1700
        User-Name = "tuxper"
        Cisco-Account-Info = "Syy.yy.30.2"
        Cisco-AVPair = "subscriber:command=account-logoff"
Finished request 8.
Cleaning up request 8 ID 98 with timestamp +248
Going to the next request
Waking up in 2.1 seconds.
rad_recv: CoA-ACK packet from host xx.xx.64.94 port 1700, id=10, length=82
Ignoring proxy reply that arrived after we sent a reply to the NAS
Waking up in 2.1 seconds.
rad_recv: Accounting-Request packet from host xx.xx.64.94 port 1646, id=102, length=467
        Acct-Session-Id = "000001A2"
        Framed-Protocol = PPP
        Framed-Route = "yy.yy.26.196 255.255.255.252 0.0.0.0 12"
        Framed-Route = "yy.yy.30.100 255.255.255.252 0.0.0.0 12"
        Framed-IP-Address = yy.yy.30.2
        Cisco-AVPair = "ppp-disconnect-cause=Lower Layer disconnected"
        User-Name = "tuxper"
        Acct-Authentic = RADIUS
        Cisco-AVPair = "connect-progress=LAN Ses Up"
        Cisco-AVPair = "nas-tx-speed=1000000000"
        Cisco-AVPair = "nas-rx-speed=1000000000"
        Acct-Session-Time = 57
        Acct-Input-Octets = 1411
        Acct-Output-Octets = 208
        Acct-Input-Packets = 17
        Acct-Output-Packets = 11
        Acct-Terminate-Cause = User-Request
        Cisco-AVPair = "disc-cause-ext=TS User Exit"
        Acct-Status-Type = Stop
        Calling-Station-Id = "00-26-b6-11-7b-84"
        NAS-Port-Type = Virtual
        NAS-Port = 0
        NAS-Port-Id = "0/0/2/25"
        Cisco-AVPair = "client-mac-address=0026.b611.7b84"
        Service-Type = Framed-User
        NAS-IP-Address = xx.xx.64.94
        Acct-Delay-Time = 0
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address = xx.xx.64.94,NAS-IP-Address = xx.xx.64.94,Acct-Session-Id = "000001A2",User-Name = "tuxper"'
[acct_unique] Acct-Unique-Session-ID = "139952617a244d89".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "tuxper", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
+- entering group accounting {...}
[detail]        expand: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radius/radacct/xx.xx.64.94/detail-20100325
[detail] /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.64.94/detail-20100325
[detail]        expand: %t -> Thu Mar 25 10:03:51 2010
++[detail] returns ok
++[unix] returns ok
[radutmp]       expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp]       expand: %{User-Name} -> tuxper
++[radutmp] returns ok
[sql]   expand: %{User-Name} -> tuxper
[sql] sql_set_user escaped user --> 'tuxper'
[sql]   expand: %{Acct-Input-Gigawords} ->
[sql]   ... expanding second conditional
[sql]   expand: %{Acct-Input-Octets} -> 1411
[sql]   expand: %{Acct-Output-Gigawords} ->
[sql]   ... expanding second conditional
[sql]   expand: %{Acct-Output-Octets} -> 208
[sql]   expand: %{Acct-Delay-Time} -> 0
[sql]   expand:            UPDATE radacct SET              acctstoptime       = '%S',              acctsessiontime    = '%{Acct-Session-Time}',              acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Output-Octets}:-0}',              acctterminatecause = '%{Acct-Terminate-Cause}',              acctstopdelay      = '%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   = '%{Connect-Info}'           WHERE acctsessionid   = '%{Acct-Session-Id}'           AND username          = '%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}' ->            UPDATE radacct SET              acctstoptime       = '2010-03-25 10:03:51',              acctsessiontime    = '57',              acctinputoctets    = '0' << 32 |                                   '1411',              acctoutputoctets   = '0' << 32 |
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
[attr_filter.accounting_response]       expand: %{User-Name} -> tuxper
 attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
++? if ("%{Acct-Status-Type}" != "Stop")
        expand: %{Acct-Status-Type} -> Stop
? Evaluating ("%{Acct-Status-Type}" != "Stop") -> FALSE
++? if ("%{Acct-Status-Type}" != "Stop") -> FALSE
Sending Accounting-Response of id 102 to xx.xx.64.94 port 1646
Finished request 9.
Cleaning up request 9 ID 102 with timestamp +248
Going to the next request
Waking up in 2.1 seconds.
Sending CoA-Request of id 10 to xx.xx.64.94 port 1700
        User-Name = "tuxper"
        Cisco-Account-Info = "Syy.yy.30.2"
        Cisco-AVPair = "subscriber:command=account-logoff"
Waking up in 4.0 seconds.
rad_recv: CoA-NAK packet from host xx.xx.64.94 port 1700, id=10, length=57
No outstanding request was found for reply from host xx.xx.64.94 port 1700 - ID 10
Waking up in 4.0 seconds.
Sending CoA-Request of id 10 to xx.xx.64.94 port 1700
        User-Name = "tuxper"
        Cisco-Account-Info = "Syy.yy.30.2"
        Cisco-AVPair = "subscriber:command=account-logoff"
Waking up in 8.2 seconds.
rad_recv: CoA-NAK packet from host xx.xx.64.94 port 1700, id=10, length=57
No outstanding request was found for reply from host xx.xx.64.94 port 1700 - ID 10
Waking up in 8.2 seconds.
Sending CoA-Request of id 10 to xx.xx.64.94 port 1700
        User-Name = "tuxper"
        Cisco-Account-Info = "Syy.yy.30.2"
        Cisco-AVPair = "subscriber:command=account-logoff"
Waking up in 15.5 seconds.
rad_recv: CoA-NAK packet from host xx.xx.64.94 port 1700, id=10, length=57
No outstanding request was found for reply from host xx.xx.64.94 port 1700 - ID 10
Waking up in 15.4 seconds.
No response to CoA request sent to xx.xx.64.94
Finished request 8.
Cleaning up request 8 ID 98 with timestamp +248
Ready to process requests.

P.S.  If send Disconnect Packet to NAS,
Freeradius doesn't recognize Disconnect-ACK and Disconnect-NAK from NAS too.
-- 
С уважением,
 Rabidinov                          mailto:tuxper@mail.ru

Freeradius doesn't accept CoA-ACK or CoA-NAK.

Rabidinov M.A.