[tac_plus] tac_plus problem
rishat
rishat at melt.ru
Tue Jun 2 16:39:45 UTC 2009
Good Day
I am system administrator in ISP
And encountered problem with tac_plus
I use complex user configuration like this one
group = unlim2048_promo {
default service = deny
service = exec {
autocmd = "ppp"
}
service = ppp protocol = lcp {
interface-config#1="service-policy output UNLIM2048_PROMO"
interface-config#2="service-policy input UNLIM_2_IN"
}
service = ppp protocol = multilink {
max-links = 1
}
after authorization "/usr/melt/tacacs+/unlim $user $name $port $address $priv $method $type $service $status"
}
user = rish { member = unlim2048_promo global = cleartext "1234"
service=ppp protocol=ip { addr-pool="PROMO" outacl="141" }}
Authentication and authorization works fine. Accounting is a problem.
The problem appeered after I added these lines in group config:
service = ppp protocol = lcp {
interface-config#1="service-policy output UNLIM2048_PROMO"
interface-config#2="service-policy input UNLIM_2_IN"
}
Here is what I see in the log and debug
When Cisco NAS sends START record there are errors as follows in
output of cisco debug:
Jun 2 14:44:46.969: TPLUS: Queuing AAA Accounting request 347933 for processing
5w6d: %LINK-3-UPDOWN: Interface Virtual-Access62, changed state to up
Jun 2 14:44:46.973: TPLUS: processing accounting request id 347933
Jun 2 14:44:46.973: TPLUS: Using directed server 89.184.0.24
Jun 2 14:44:46.973: TPLUS: Sending AV task_id=404050
Jun 2 14:44:46.973: TPLUS: Sending AV timezone=MSD
Jun 2 14:44:46.973: TPLUS: Sending AV service=ppp
Jun 2 14:44:46.973: TPLUS: Sending AV start_time=1243939485
Jun 2 14:44:46.973: TPLUS: Sending AV clid-mac-addr=0015.e941.1fe0
Jun 2 14:44:46.973: TPLUS: Sending AV sub-policy-In=UNLIM_2_IN
Jun 2 14:44:46.973: TPLUS: Sending AV sub-policy-Out=UNLIM2048_PROMO
Jun 2 14:44:46.973: TPLUS: Sending AV Framed-Protocol=1
Jun 2 14:44:46.973: TPLUS: Sending AV client-mac-address=0015.e941.1fe0
Jun 2 14:44:46.973: TPLUS: Accounting request created for 347933(rish)
Jun 2 14:44:46.973: TPLUS(00054F1D)/0/NB_WAIT/66461874: Started 5 sec timeout
Jun 2 14:44:46.981: TPLUS(00054F1D)/0/NB_WAIT: socket event 2
Jun 2 14:44:46.981: TPLUS(00054F1D)/0/NB_WAIT: wrote entire 231 bytes request
Jun 2 14:44:46.981: TPLUS(00054F1D)/0/READ: socket event 1
Jun 2 14:44:46.981: TPLUS(00054F1D)/0/READ: Would block while reading
Jun 2 14:44:47.005: TPLUS(00054F1D)/0/READ: socket event 1
Jun 2 14:44:47.005: TPLUS(00054F1D)/0/READ: read entire 12 header bytes (expect 5 bytes data)
Jun 2 14:44:47.005: TPLUS(00054F1D)/0/READ: socket event 1
Jun 2 14:44:47.005: TPLUS(00054F1D)/0/READ: read entire 17 bytes response
Jun 2 14:44:47.005: TPLUS(00054F1D)/0/66461874: Processing the reply packet
Jun 2 14:44:47.005: TPLUS: Received accounting response with status PASS
And here is what we get in log of tac_plus:
Tue Jun 2 15:28:28 2009 [10015]: Read ACCT size=231
Tue Jun 2 15:28:28 2009 [10015]: validation request from 89.184.0.121
Tue Jun 2 15:28:28 2009 [10015]: PACKET: key=xxxx
Tue Jun 2 15:28:28 2009 [10015]: version 192 (0xc0), type 3, seq no 1, flags 0x1
Tue Jun 2 15:28:28 2009 [10015]: session_id 149227973 (0x8e509c5), Data length 219 (0xdb)
Tue Jun 2 15:28:28 2009 [10015]: End header
Tue Jun 2 15:28:28 2009 [10015]: Packet body hex dump:
Tue Jun 2 15:28:28 2009 [10015]: 0x2 0x6 0x1 0x3 0x3 0x4 0x7 0x0 0x9 0xe 0xc 0xb 0x15 0x1c 0x18 0x1e 0x11 0x21
Tue Jun 2 15:28:28 2009 [10015]: 0x72 0x69 0x73 0x68 0x30 0x2f 0x30 0x2f 0x30 0x2f 0x33 0x74 0x61 0x73 0x6b 0x5f
Tue Jun 2 15:28:28 2009 [10015]: 0x69 0x64 0x3d 0x34 0x30 0x34 0x32 0x36 0x36 0x74 0x69 0x6d 0x65 0x7a 0x6f 0x6e
Tue Jun 2 15:28:28 2009 [10015]: 0x65 0x3d 0x4d 0x53 0x44 0x73 0x65 0x72 0x76 0x69 0x63 0x65 0x3d 0x70 0x70 0x70
Tue Jun 2 15:28:28 2009 [10015]: 0x73 0x74 0x61 0x72 0x74 0x5f 0x74 0x69 0x6d 0x65 0x3d 0x31 0x32 0x34 0x33 0x39
Tue Jun 2 15:28:28 2009 [10015]: 0x34 0x32 0x31 0x30 0x37 0x63 0x6c 0x69 0x64 0x2d 0x6d 0x61 0x63 0x2d 0x61 0x64
Tue Jun 2 15:28:28 2009 [10015]: 0x64 0x72 0x3d 0x30 0x30 0x31 0x35 0x2e 0x65 0x39 0x34 0x31 0x2e 0x31 0x66 0x65
Tue Jun 2 15:28:28 2009 [10015]: 0x30 0x73 0x75 0x62 0x2d 0x70 0x6f 0x6c 0x69 0x63 0x79 0x2d 0x49 0x6e 0x3d 0x55
Tue Jun 2 15:28:28 2009 [10015]: 0x4e 0x4c 0x49 0x4d 0x5f 0x32 0x5f 0x49 0x4e 0x73 0x75 0x62 0x2d 0x70 0x6f 0x6c
Tue Jun 2 15:28:28 2009 [10015]: 0x69 0x63 0x79 0x2d 0x4f 0x75 0x74 0x3d 0x55 0x4e 0x4c 0x49 0x4d 0x32 0x30 0x34
Tue Jun 2 15:28:28 2009 [10015]: 0x38 0x5f 0x50 0x52 0x4f 0x4d 0x4f 0x46 0x72 0x61 0x6d 0x65 0x64 0x2d 0x50 0x72
Tue Jun 2 15:28:28 2009 [10015]: 0x6f 0x74 0x6f 0x63 0x6f 0x6c 0x3d 0x31 0x63 0x6c 0x69 0x65 0x6e 0x74 0x2d 0x6d
Tue Jun 2 15:28:28 2009 [10015]: 0x61 0x63 0x2d 0x61 0x64 0x64 0x72 0x65 0x73 0x73 0x3d 0x30 0x30 0x31 0x35 0x2e
Tue Jun 2 15:28:28 2009 [10015]: 0x65 0x39 0x34 0x31 0x2e 0x31 0x66 0x65 0x30
Tue Jun 2 15:28:28 2009 [10015]: ACCT, flags=0x2 method=6 priv_lvl=1
Tue Jun 2 15:28:28 2009 [10015]: type=3 svc=3
Tue Jun 2 15:28:28 2009 [10015]: Bad ACCT packet length -620756992
Tue Jun 2 15:28:28 2009 [10015]: Start accounting request
Tue Jun 2 15:28:28 2009 [10015]: 'Tue Jun 2 15:28:28 2009'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: '89.184.0.121'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'rish'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: '0/0/0/3'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'unknown'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'start '
Tue Jun 2 15:28:28 2009 [10015]: 'task_id=404266'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'timezone=MSD'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'service=ppp'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'start_time=1243942107'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'clid-mac-addr=0015.e941.1fe0'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'sub-policy-In=UNLIM_2_IN'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'sub-policy-Out=UNLIM2048_PROMO'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'Framed-Protocol=1'
Tue Jun 2 15:28:28 2009 [10015]: ' '
Tue Jun 2 15:28:28 2009 [10015]: 'client-mac-address=0015.e941.1fe0'
Tue Jun 2 15:28:28 2009 [10015]: '
'
Tue Jun 2 15:28:28 2009 [10015]: Writing ACCT size=17
Tue Jun 2 15:28:28 2009 [10015]: PACKET: key=xxx
Tue Jun 2 15:28:28 2009 [10015]: version 192 (0xc0), type 3, seq no 2, flags 0x1
Tue Jun 2 15:28:28 2009 [10015]: session_id 149227973 (0x8e509c5), Data length 5 (0x5)
Tue Jun 2 15:28:28 2009 [10015]: End header
Tue Jun 2 15:28:28 2009 [10015]: Packet body hex dump:
Tue Jun 2 15:28:28 2009 [10015]: 0x0 0x0 0x0 0x0 0x1
Tue Jun 2 15:28:28 2009 [10015]: ACCT/REPLY status=1
Tue Jun 2 15:28:28 2009 [10015]: msg_len=0 data_len=0
Tue Jun 2 15:28:28 2009 [10015]: msg:
Tue Jun 2 15:28:28 2009 [10015]: data:
Tue Jun 2 15:28:28 2009 [10015]: End packet
Nevertheless tac_plus logs START record in a log file:
Tue Jun 2 14:44:46 2009 89.184.0.121 rish 0/0/0/3 unknown start task_id=404050 timezone=MSD
service=ppp start_time=1243939485 clid-mac-addr=0015.e941.1fe0 sub-policy-In=UNLIM_2_IN
sub-policy-Out=UNLIM2048_PROMO Framed-Protocol=1 client-mac-address=0015.e941.1fe0
The real problem is when NAS sends STOP record.
Here is what I see in the output of cisco debug
Jun 2 14:44:59.061: TPLUS: Queuing AAA Accounting request 347933 for processing
Jun 2 14:44:59.061: TPLUS: processing accounting request id 347933
Jun 2 14:44:59.061: TPLUS: Using directed server 89.184.0.24
Jun 2 14:44:59.061: TPLUS: Sending AV task_id=404050
Jun 2 14:44:59.061: TPLUS: Sending AV timezone=MSD
Jun 2 14:44:59.061: TPLUS: Sending AV service=ppp
Jun 2 14:44:59.061: TPLUS: Sending AV start_time=1243939485
Jun 2 14:44:59.061: TPLUS: Sending AV clid-mac-addr=0015.e941.1fe0
Jun 2 14:44:59.061: TPLUS: Sending AV sub-policy-In=UNLIM_2_IN
Jun 2 14:44:59.061: TPLUS: Sending AV sub-policy-Out=UNLIM2048_PROMO
Jun 2 14:44:59.061: TPLUS: Sending AV Framed-Protocol=1
Jun 2 14:44:59.061: TPLUS: Sending AV protocol=ip
Jun 2 14:44:59.065: TPLUS: Sending AV addr=89.184.30.31
Jun 2 14:44:59.065: TPLUS: Sending AV ppp-disconnect-cause=Received LCP TERMREQ from peer
Jun 2 14:44:59.065: TPLUS: Sending AV pre-session-time=1
Jun 2 14:44:59.065: TPLUS: Sending AV nas-tx-speed=100000000
Jun 2 14:44:59.065: TPLUS: Sending AV nas-rx-speed=100000000
Jun 2 14:44:59.065: TPLUS: Sending AV elapsed_time=13
Jun 2 14:44:59.065: TPLUS: Sending AV stop_time=1243939499
Jun 2 14:44:59.065: TPLUS: Sending AV bytes_in=1133
Jun 2 14:44:59.065: TPLUS: Sending AV bytes_out=364
Jun 2 14:44:59.065: TPLUS: Sending AV pre-bytes-in=183
Jun 2 14:44:59.065: TPLUS: Sending AV pre-bytes-out=118
Jun 2 14:44:59.065: TPLUS: Sending AV paks_in=15
Jun 2 14:44:59.065: TPLUS: Sending AV paks_out=9
Jun 2 14:44:59.065: TPLUS: Sending AV pre-paks-in=7
Jun 2 14:44:59.065: TPLUS: Sending AV pre-paks-out=6
Jun 2 14:44:59.065: TPLUS: Sending AV disc-cause=1
Jun 2 14:44:59.065: TPLUS: Sending AV disc-cause-ext=28
Jun 2 14:44:59.065: TPLUS: Sending AV client-mac-address=0015.e941.1fe0
Jun 2 14:44:59.065: TPLUS: Accounting request created for 347933(rish)
Jun 2 14:44:59.065: TPLUS(00054F1D)/0/NB_WAIT/66461874: Started 5 sec timeout
Jun 2 14:44:59.069: TPLUS(00054F1D)/0/NB_WAIT: socket event 2
Jun 2 14:44:59.069: TPLUS(00054F1D)/0/NB_WAIT: wrote 536 bytes
5w6d: %LINK-3-UPDOWN: Interface Virtual-Access62, changed state to down
5w6d: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access62, changed state to down
And here is what we get in log of tac_plus:
Tue Jun 2 17:42:06 2009 [10010]: session.peerip is 89.184.0.121
Tue Jun 2 17:42:06 2009 [10010]: session request from 89.184.0.121 sock=2
Tue Jun 2 17:42:06 2009 [46296]: connect from 89.184.0.121 [89.184.0.121]
Tue Jun 2 17:42:06 2009 [46296]: Waiting for packet
Tue Jun 2 17:42:11 2009 [46296]: 89.184.0.121 : fd 2 eof (connection closed)
Tue Jun 2 17:42:11 2009 [46296]: Error 89.184.0.121: start_session:
bad socket read
This time tac_plus logs nothing in accounting log
Could you please look at my case and saggest some decision
With respect
Rishat N Agzamov, CCNP, HP-AIS, MCP
Leading system engineer MELT LLC
ph. (843) 299-50-43 mailto:rishat at melt.ru
More information about the tac_plus
mailing list