[cisco-bba] Multiple Radius Accounting

Tue Sep 16 16:47:22 EDT 2003

Please turn on "Debug radius accounting" to see if the router is
receiving the acknowledgements.

Dennis

Tay Chee Yong [tcy at pacific.net.sg] wrote:
> 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
> _______________________________________________
> cisco-bba mailing list
> cisco-bba at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-bba