[cisco-bba] Multiple Radius Accounting

Mon Sep 15 20:31:33 EDT 2003

Hi all,

I am using a Cisco 7206 router as BB aggregator. I seems to be getting
multiple accounting start/stop packets on the radius server.

I noticed from the tcpdump output that despite acknowledgement from the
radius server, the 7206 is still sending the start packet to the radius
server. (Observe the time of the debug and tcpdump output)

A "debug aaa accounting" shows the following in the Cisco 7206:

Start Accounting:

Sep 15 19:08:08: AAA/ACCT/CLIENT(0000000B): recv 153354240bps xmit
153354240bps
Sep 15 19:08:08: AAA/ACCT/HC(0000000B): Register PPoE/63801ACC 153Mbit/s,
poll every 30.3000s
Sep 15 19:08:08: AAA/ACCT/HC(0000000B): Update PPoE/63801ACC
Sep 15 19:08:08: AAA/ACCT/HC(0000000B): PPoE/63801ACC [init-sess] (rx/tx)
base 0/0 pre 0/0 call 0/0
Sep 15 19:08:08: AAA/ACCT/HC(0000000B): PPoE/63801ACC [init-sess] (rx/tx)
adjusted, pre 0/0 call 0/0
Sep 15 19:08:08: AAA/ACCT/EVENT/(0000000B): CALL START
Sep 15 19:08:08: Getting session id for NET(0000000B) : db=64589038
Sep 15 19:08:08: AAA/ACCT(00000000): add node, session 155
Sep 15 19:08:08: AAA/ACCT/NET(0000000B): add, count 1
Sep 15 19:08:08: AAA/ACCT/NET(0000000B): Pick method list 'default'
Sep 15 19:08:08: AAA/ACCT/SETMLIST(0000000B): Handle 0, mlist 63CDD44C,
Name default
Sep 15 19:08:08: AAA/ACCT/EVENT/(0000000B): ATTR REPLACE
Sep 15 19:08:18: Getting session id for NET(0000000B) : db=64589038
Sep 15 19:08:18: AAA/ACCT/NET(0000000B): Pick method list 'default'
Sep 15 19:08:18: AAA/ACCT/SETMLIST(0000000B): Handle 0, mlist 63CDD44C,
Name default
Sep 15 19:08:18: AAA/ACCT/EVENT/(0000000B): NET UP
Sep 15 19:08:18: AAA/ACCT/CLIENT(0000000B): recv 153354240bps xmit
153354240bps
Sep 15 19:08:18: AAA/ACCT/HC(0000000B): Update PPoE/63801ACC
Sep 15 19:08:18: AAA/ACCT/HC(0000000B): PPoE/63801ACC [pre-sess] (rx/tx)
base 0/0 pre 101/95 call 101/95
Sep 15 19:08:18: AAA/ACCT/HC(0000000B): PPoE/63801ACC [pre-sess] (rx/tx)
adjusted, pre 101/95 call 0/0
Sep 15 19:08:18: AAA/ACCT/NET(0000000B): Queueing record is START
Sep 15 19:08:18: AAA/ACCT(0000000B): Accouting method=radius (radius)
Sep 15 19:08:19: AAA/ACCT/EVENT/(0000000B): IPCP_PASS
Sep 15 19:08:38: AAA/ACCT/NET(0000000B): START protocol reply FAIL
Sep 15 19:08:38: AAA/ACCT(0000000B): Accouting method=NOT_SET

Stop accounting

Sep 15 19:09:03: AAA/ACCT/NET(0000000B): Pick method list 'default'
Sep 15 19:09:03: AAA/ACCT/SETMLIST(0000000B): Handle 0, mlist 63CDD44C,
Name default
Sep 15 19:09:03: AAA/ACCT/EVENT/(0000000B): NET DOWN
Sep 15 19:09:03: AAA/ACCT/CLIENT(0000000B): recv 153354240bps xmit
153354240bps
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): Update PPoE/63801ACC
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): PPoE/63801ACC [sess] (rx/tx) base
0/0 pre 101/95 call 2891/1811
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): PPoE/63801ACC [sess] (rx/tx)
adjusted, pre 101/95 call 2790/1716
Sep 15 19:09:03: AAA/ACCT/NET(0000000B): Queueing record is STOP osr 1
Sep 15 19:09:03: AAA/ACCT(0000000B): del node, session 155
Sep 15 19:09:03: AAA/ACCT/NET(0000000B): free_rec, count 0
Sep 15 19:09:03: AAA/ACCT/NET(0000000B): Setting session id 165 :
db=64589038
Sep 15 19:09:03: AAA/ACCT(0000000B): Accouting method=radius (radius)
Sep 15 19:09:03: AAA/ACCT/EVENT/(0000000B): NET DOWN
Sep 15 19:09:03: AAA/ACCT(0000000B): Duplicate action NET DOWN
Sep 15 19:09:03: AAA/ACCT/CLIENT(0000000B): recv 153354240bps xmit
153354240bps
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): Update PPoE/63801ACC
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): PPoE/63801ACC [sess] (rx/tx) base
0/0 pre 101/95 call 2891/1811
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): PPoE/63801ACC [sess] (rx/tx)
adjusted, pre 101/95 call 2790/1716
Sep 15 19:09:03: AAA/ACCT/HC(0000000B): Deregister PPoE/63801ACC
Sep 15 19:09:03: AAA/ACCT/EVENT/(0000000B): CALL STOP
Sep 15 19:09:03: AAA/ACCT(0000000B) reccnt 0, osr 1
Sep 15 19:09:23: AAA/ACCT/NET(0000000B): STOP protocol reply FAIL
Sep 15 19:09:23: AAA/ACCT(0000000B): Accouting method=NOT_SET
Sep 15 19:09:23: AAA/ACCT/NET(0000000B): Tried all the methods, osr 0
Sep 15 19:09:23: AAA/ACCT/NET(0000000B) Record not present
Sep 15 19:09:23: AAA/ACCT/NET(0000000B) reccnt 0, csr TRUE, osr 0
Sep 15 19:09:23: AAA/ACCT/NET(0000000B): Last rec in db, intf not enqueued

A tcpdump from my radius server:

19:08:18.945248 10.10.10.2.21645 > 20.20.20.114.datametrics:
rad-access-req 91 [id 49] Attr[  Framed_proto{#257} User{test at domain.net}
[|radius] (ttl 253, id 6670, len 119)
19:08:18.955248 20.20.20.114.datametrics > 10.10.10.2.21645:
rad-access-accept 55 [id 49] Attr[  Service_type{#538} [|radius] (DF) (ttl
64, id 0, len 83)
19:08:18.965249 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 101 [id 50] Attr[  Acct_session_id{0000009B}
Framed_proto{#301} Acct_authentic{#257} [|radius] (ttl 253, id 6671, len
129)
19:08:23.965408 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 101 [id 51] Attr[  Acct_session_id{0000009B}
Framed_proto{#301} Acct_authentic{#257} [|radius] (ttl 253, id 6703, len
129)
19:08:28.975567 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 101 [id 52] Attr[  Acct_session_id{0000009B}
Framed_proto{#301} Acct_authentic{#257} [|radius] (ttl 253, id 6723, len
129)
19:08:33.965726 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 101 [id 53] Attr[  Acct_session_id{0000009B}
Framed_proto{#301} Acct_authentic{#257} [|radius] (ttl 253, id 6733, len
129)

19:09:03.076652 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 143 [id 54] Attr[  Acct_session_id{0000009B}
Framed_proto{#264} Framed_ipaddr{3.3.3.82} Acct_authentic{#302}
Acct_session_time{44 secs} ] (ttl 253, id 6845, len 171)
19:09:08.076811 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 143 [id 55] Attr[  Acct_session_id{0000009B}
Framed_proto{#264} Framed_ipaddr{3.3.3.82} Acct_authentic{#302}
Acct_session_time{44 secs} ] (ttl 253, id 6863, len 171)
19:09:13.076970 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 143 [id 56] Attr[  Acct_session_id{0000009B}
Framed_proto{#264} Framed_ipaddr{3.3.3.82} Acct_authentic{#302}
Acct_session_time{44 secs} ] (ttl 253, id 6878, len 171)
19:09:18.077129 10.10.10.2.21645 > 20.20.20.114.sa-msg-port:
rad-account-req 143 [id 57] Attr[  Acct_session_id{0000009B}
Framed_proto{#264} Framed_ipaddr{3.3.3.82} Acct_authentic{#302}
Acct_session_time{44 secs} ] (ttl 253, id 6903, len 171)

Could anyone explain to me why is this happening?

Thanks.

Regards,
Cheeyong