[cisco-nas] Hst No Carr issue
Thai Duy Hoa
tdhoa at istt.com.vn
Fri Oct 29 00:05:36 EDT 2004
Dear Aaron
Thanks for your prompt reply.
However, our customers claim a lot about the unexpected disconnections. That
means we should investigate more.
I have opened a TAC case # 600427353 for nearly 02 months and Vadim
Zakharine [vzakhari at cisco.com] is the owner now.
I'm sure you can read the chain for my case.
The main cause is when some specific condition happen (don't now yet), the
Next port modem and client modem retrain to find a new speed.
If the retrain success, they continue to work.
If the retrain fail, Nextport itseld terminate and make the call dropped
with DR 0x1F06 for Nextport and DR 0xDF06 for MICA.
I have turn on the following debug and watched very carefully
debug cas
debug sigsm r2
debug sig sm digits
debug modem
debug call-mgmt
debug calltracker
debug csm modem
debug spe sm
debug ppp nego
debug ppp authen
debug dialer
debug ppp error
debug radius authentication
debug radius accounting
debug radius author
debug sigsm api
debug nextport ssm detail
debug nextport siglib detail
>
> What makes you think that this "Hst No Carr" value is too big?
> The NextPort "Hst No Carr" is basically a "network indicated
> disconnect" or in other words, a circuit disconnect received
> from the PSTN. You can see a discussion of this disconnect type
> at
> http://www.cisco.com/en/US/tech/tk801/tk36/technologies_tech_note09186a008
> 0094ebb.shtml#table7
> (0x1F06), also see the appended writeup I did on understanding
> modem disconnects for a customer.
I have read this doc many times, but it's only general causes
>
> In the case where IOS is informed of a disconnection due
> to a hangup from the server-side modem (i.e. loss of Carrier
> Detect, which IOS calls "DSR"), this will be reported as
> Disconnect-Cause = 11, "Lost-Carrier".)
I have turned on Cisco VSA and the main cause from VSA is
*Oct 27 20:23:47: RADIUS: Acct-Terminate-Cause[49] 6 lost-carrier
[2]
*Oct 27 20:23:47: RADIUS: Vendor, Cisco [26] 33
*Oct 27 20:23:47: RADIUS: Cisco AVpair [1] 27 "disc-cause-ext=No
Carrier"
*Oct 27 20:23:47: RADIUS: Vendor, Cisco [26] 35
*Oct 27 20:23:47: RADIUS: Cisco AVpair [1] 29
"connect-progress=LAN Ses Up"
>
> a) Examine the contents of the 196 ("Connect-Progress") attribute.
> In order to use this field for PPP calls, you must be running
> IOS 12.2(2) or above (DDTS CSCdr90345.) This will support, for
> PPP connections, the following Connect-Progress field values:
>
> 60 LAN Session up (i.e. IPCP negotiations complete)
> 65 LCP Open (i.e. PPP negotiations beginning)
> 67 IPCP Open (i.e. IPCP negotiations beginning)
>
> Therefore, for PPP/IPCP calls, if attribute 196=60, then you can
> infer that the disconnect happened after the call had successfully
> completed.
>
> In current IOS 12.2XB/12.2T (CSCdr63648), additional attribute 196
> field values are provided: 10, 31 and 32 (for states that precede
> the advent of LCP Open.)
>
> b) Examine the contents of Framed-IP-Address (attribute 8). If a valid
> IP address is found, then you can infer that IPCP had successfully
> negotiated. This attribute is provided with RADIUS accounting records
> in all IOS versions.
>
> For L2x-forwarded VPN calls, the Framed-IP-Address contents will
> not be available to determine that the call succeeded. In my
> research, I was unable to tell what Connect-Progress value will
> be provided by the LAC for for a successful call; further research/
> experimentation will be required to figure that out.
>
> Now: to tell whether a cause 11 disconnect is "good" or "bad"
> (for non-VPN calls), you can follow the following heuristic:
>
> - if the disconnect occurred before IPCP was complete (attr 196=60
> or Framed-IP-Address valid), then you can infer that the disconnect
> was "bad".
>
> - if the disconnect occurred after IPCP completed, then a cause 11
> disconnect may or may not be bad. To further analyze the disconnect,
> you will want to examine the modem disconnect reason.
>
> The modem disconnect reason is not provided to RADIUS accounting;
> you can access it via "modem call-record terse", which reports to
> SYSLOG, or via the Call Tracker feature (which reports to SYSLOG
> and/or SNMP.) An explanation of the MICA modem disconnect reasons
> is given in the CCO Tech Note "MICA Modem States and Disconnect Reasons"
> (http://www.cisco.com/warp/public/76/mica-states-drs.html.)
>
> Examples of GOOD modem disconnect reasons include (here the disconnect
> codes are given with the type code masked off - e.g. an 0x8220 disconnect
> would be given as 0x220):
>
> 0x220 Received LAPM DISC frame - graceful LAPM disconnect
> 0x5FF Received MNP LD frame - graceful MNP disconnect
>
> Other disconnects may or may not be "bad". For example, a
>
> 0x1F06 Network indicated disconnect
>
> which indicates that the NAS received a disconnect message from
> the PSTN's signaling layer, may be a "good" disconnect if an
> error control protocol was not negotiated on the modem link,
> or if the end user's preferred method of call termination is to
> unplug the phone cable or power off the modem. However, if
> the call did negotiate LAPM, and if the user did not abruptly
> disconnect the transmission path, then an 0x1F06 disconnect is
> PROBABLY "bad". (Similarly for a DSP-layer lost carrier
> disconnect, 0x100.)
I understand the whole picture you showed.
However, pls. see below for one of the failed calls (watched on MICA), and
same issue with Nextport
*Oct 28 21:43:53: CSM_PROC_IC1_COLLECT_ADDR_INFO:
CSM_EVENT_ADDR_INFO_COLLECTED (DNIS=12777, ANI=48586127) at slot 1, port 50
*Oct 28 21:43:53: CSM_SEND_NEAT_CAS_EVENT(1/50): EVENT_END_RX_TONE
*Oct 28 21:43:54: CSM/CT: Allocated call handle 510
*Oct 28 21:43:54: Mica Modem(1/50): Link Initiate
*Oct 28 21:43:54: CT: setup: issued hndl=510 for call_cat=3(Voice),
called=12777, calling=48586127
*Oct 28 21:43:54: CT: Successfully inserted active call-record entry
hndl=510 into table.
*Oct 28 21:43:54: CT: dsp allocated: hndl=510, slot/port=1/50
*Oct 28 21:43:54: CT: call connected: hndl=510,
idb=0x0(), call-cat=3(Voice), rate=0,
slot/port/ds1/chan=0/0/0/30
*Oct 28 21:43:54: In actv_c_proc_message,
access type CPM_INSERT_NEW_CALL,
call type CPM_CT1_ANALOG:
CSM completed connecting a new modem call
*Oct 28 21:43:55: Mica Modem(1/50): State Transition to Connect
*Oct 28 21:43:55: Mica Modem(1/50): State Transition to V8bis Exchange
*Oct 28 21:43:57: Mica Modem(1/50): State Transition to Quick Connect
*Oct 28 21:43:59: Mica Modem(1/50): State Transition to Ranging Short
*Oct 28 21:43:59: Mica Modem(1/50): State Transition to Half Duplex Train
*Oct 28 21:44:05: Mica Modem(1/50): State Transition to Trainup
*Oct 28 21:44:08: Mica Modem(1/50): State Transition to EC Negotiating
*Oct 28 21:44:09: Mica Modem(1/50): State Transition to Steady State
*Oct 28 21:44:09: CT: dsp negotiated: hndl=510
*Oct 28 21:44:09: msg_to_calls_mgmt: msg type CPM_NEW_CALL_ISDN_CONNECT
received
*Oct 28 21:44:09: TTY51: DSR came up
*Oct 28 21:44:09: Unthrottle 51
*Oct 28 21:44:09: TTY51: no timer type 1 to destroy
*Oct 28 21:44:09: TTY51: no timer type 0 to destroy
*Oct 28 21:44:09: TTY51: no timer type 2 to destroy
*Oct 28 21:44:09: tty51: Modem: IDLE->(unknown)
*Oct 28 21:44:09: In actv_c_proc_message,
access type CPM_INSERT_NEW_CALL,
call type CPM_CT1_ANALOG:
Added a new CT1 analog call to the active-calls list
CC-Slot#0, DSX1-Ctrlr#0, DS0-Timeslot#31
Mdm-Slot#1, Mdm-Port#50, TTY#51
*Oct 28 21:44:09: As51 LCP: I CONFREQ [Closed] id 1 len 23
*Oct 28 21:44:09: As51 LCP: ACCM 0x000A0000 (0x0206000A0000)
*Oct 28 21:44:09: As51 LCP: MagicNumber 0x00026F6A (0x050600026F6A)
*Oct 28 21:44:09: As51 LCP: PFC (0x0702)
*Oct 28 21:44:09: As51 LCP: ACFC (0x0802)
*Oct 28 21:44:09: As51 LCP: Callback 6 (0x0D0306)
*Oct 28 21:44:09: As51 LCP: Lower layer not up, Fast Starting
*Oct 28 21:44:09: AS_ST_MODEM_INFO(1/50): init rx/tx 26400/40000 current
rx/tx 28800/37333
*Oct 28 21:44:09: AS_ST_MODEM_INFO(1/50): compression 0/None, modulation
12/V90, protocol 4/LAPM
*Oct 28 21:44:09: AAA/BIND(0000029C): Bind i/f Async51
*Oct 28 21:44:09: As51 PPP: Using modem call direction
*Oct 28 21:44:09: As51 PPP: Treating connection as a callin
*Oct 28 21:44:09: As51 PPP: Phase is ESTABLISHING, Passive Open
*Oct 28 21:44:09: As51 LCP: State is Listen
*Oct 28 21:44:09: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:09: As51 PPP: Authorization required
*Oct 28 21:44:09: As51 LCP: O CONFREQ [Listen] id 41 len 24
*Oct 28 21:44:09: As51 LCP: ACCM 0x000A0000 (0x0206000A0000)
*Oct 28 21:44:09: As51 LCP: AuthProto PAP (0x0304C023)
*Oct 28 21:44:09: As51 LCP: MagicNumber 0x03E86F54 (0x050603E86F54)
*Oct 28 21:44:09: As51 LCP: PFC (0x0702)
*Oct 28 21:44:09: As51 LCP: ACFC (0x0802)
*Oct 28 21:44:09: As51 LCP: O CONFREJ [Listen] id 1 len 7
*Oct 28 21:44:09: As51 LCP: Callback 6 (0x0D0306)
*Oct 28 21:44:09: CT: set AAA session id:
hndl=510, sess_id=943
*Oct 28 21:44:09: CT: set AAA session id:
hndl=510, sess_id=943
*Oct 28 21:44:09: CT: ppp start: hndl=510
*Oct 28 21:44:09.858: %LINK-3-UPDOWN: Interface Async51, changed state to up
*Oct 28 21:44:10: As51 LCP: I CONFACK [REQsent] id 41 len 24
*Oct 28 21:44:10: As51 LCP: ACCM 0x000A0000 (0x0206000A0000)
*Oct 28 21:44:10: As51 LCP: AuthProto PAP (0x0304C023)
*Oct 28 21:44:10: As51 LCP: MagicNumber 0x03E86F54 (0x050603E86F54)
*Oct 28 21:44:10: As51 LCP: PFC (0x0702)
*Oct 28 21:44:10: As51 LCP: ACFC (0x0802)
*Oct 28 21:44:10: As51 LCP: I CONFREQ [ACKrcvd] id 2 len 20
*Oct 28 21:44:10: As51 LCP: ACCM 0x000A0000 (0x0206000A0000)
*Oct 28 21:44:10: As51 LCP: MagicNumber 0x00026F6A (0x050600026F6A)
*Oct 28 21:44:10: As51 LCP: PFC (0x0702)
*Oct 28 21:44:10: As51 LCP: ACFC (0x0802)
*Oct 28 21:44:10: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:10: As51 LCP: O CONFACK [ACKrcvd] id 2 len 20
*Oct 28 21:44:10: As51 LCP: ACCM 0x000A0000 (0x0206000A0000)
*Oct 28 21:44:10: As51 LCP: MagicNumber 0x00026F6A (0x050600026F6A)
*Oct 28 21:44:10: As51 LCP: PFC (0x0702)
*Oct 28 21:44:10: As51 LCP: ACFC (0x0802)
*Oct 28 21:44:10: As51 LCP: State is Open
*Oct 28 21:44:10: As51 PPP: Phase is AUTHENTICATING, by this end
*Oct 28 21:44:10: CT: ppp start: hndl=510
*Oct 28 21:44:10: As51 PAP: I AUTH-REQ id 1 len 22 from "68984212"
*Oct 28 21:44:10: As51 PAP: Authenticating peer 68984212
*Oct 28 21:44:10: As51 PPP: Phase is FORWARDING, Attempting Forward
*Oct 28 21:44:10: As51 PPP: Phase is AUTHENTICATING, Unauthenticated User
*Oct 28 21:44:10: As51 PPP: Sent PAP LOGIN Request
*Oct 28 21:44:10: RADIUS(0000029C): Storing nasport 51 in rad_db
*Oct 28 21:44:10: RADIUS(0000029C): Config NAS IP: 0.0.0.0
*Oct 28 21:44:10: RADIUS/ENCODE(0000029C): acct_session_id: 943
*Oct 28 21:44:10: RADIUS(0000029C): sending
*Oct 28 21:44:10: RADIUS/ENCODE: Best Local IP-Address 192.168.3.21 for
Radius-Server 203.210.160.3
*Oct 28 21:44:10: RADIUS(0000029C): Send Access-Request to
203.210.160.3:1812 id 21649/199, len 162
*Oct 28 21:44:10: RADIUS: authenticator 09 04 8F 33 D2 75 05 CC - DD 9C F4
18 38 EB D7 22
*Oct 28 21:44:10: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Oct 28 21:44:10: RADIUS: User-Name [1] 10 "68984212"
*Oct 28 21:44:10: RADIUS: User-Password [2] 18 *
*Oct 28 21:44:10: RADIUS: Vendor, Cisco [26] 15
*Oct 28 21:44:10: RADIUS: cisco-nas-port [2] 9 "Async51"
*Oct 28 21:44:10: RADIUS: NAS-Port [5] 6 51
*Oct 28 21:44:10: RADIUS: NAS-Port-Type [61] 6 Async
[0]
*Oct 28 21:44:10: RADIUS: Calling-Station-Id [31] 10 "48586127"
*Oct 28 21:44:10: RADIUS: Called-Station-Id [30] 7 "12777"
*Oct 28 21:44:10: RADIUS: Connect-Info [77] 36 "37333/28800
V90/LAPM (40000/26400)"
*Oct 28 21:44:10: RADIUS: Service-Type [6] 6 Framed
[2]
*Oct 28 21:44:10: RADIUS: NAS-IP-Address [4] 6 192.168.3.21
*Oct 28 21:44:10: RADIUS: Framed-IP-Address [8] 6 192.168.3.246
*Oct 28 21:44:10: RADIUS: Acct-Session-Id [44] 10 "000003AF"
*Oct 28 21:44:10: RADIUS: Received from id 21649/199 203.210.160.3:1812,
Access-Accept, len 124
*Oct 28 21:44:10: RADIUS: authenticator CB 46 00 FA 88 BE 74 CA - DA 86 3E
F2 11 73 65 C7
*Oct 28 21:44:10: RADIUS: Class [25] 62
*Oct 28 21:44:10: RADIUS: 53 42 52 2D 43 4C 20 44 4E 3D 22 36 38 39 38 34
[SBR-CL DN="68984]
*Oct 28 21:44:10: RADIUS: 32 31 32 22 20 41 54 3D 22 32 30 30 22 20 49 50
[212" AT="200" IP]
*Oct 28 21:44:10: RADIUS: 3D 22 31 39 32 2E 31 36 38 2E 33 2E 32 33 33 22
[="192.168.3.233"]
*Oct 28 21:44:10: RADIUS: 20 53 49 3D 22 38 36 31 37 37 22 00
[ SI="86177"?]
*Oct 28 21:44:10: RADIUS: Session-Timeout [27] 6 67876
*Oct 28 21:44:10: RADIUS: Framed-IP-Address [8] 6 192.168.3.233
*Oct 28 21:44:10: RADIUS: Framed-IP-Netmask [9] 6 255.255.255.255
*Oct 28 21:44:10: RADIUS: Framed-MTU [12] 6 1500
*Oct 28 21:44:10: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Oct 28 21:44:10: RADIUS: Framed-Routing [10] 6 0
*Oct 28 21:44:10: RADIUS: Service-Type [6] 6 Framed
[2]
*Oct 28 21:44:10: RADIUS(0000029C): Received from id 21649/199
*Oct 28 21:44:10: As51 PPP: Received LOGIN Response PASS
*Oct 28 21:44:10: As51 PPP: Phase is FORWARDING, Attempting Forward
*Oct 28 21:44:10: As51 PPP: Phase is AUTHENTICATING, Authenticated User
*Oct 28 21:44:10: AAA/AUTHOR (0x29C): Pick method list 'default'
*Oct 28 21:44:10: As51 PPP: Sent LCP AUTHOR Request
*Oct 28 21:44:10: RADIUS/ENCODE(0000029C): send packet; PASS
*Oct 28 21:44:10: As51 LCP: Received AAA AUTHOR Response PASS
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: timeout: Peruser
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: addr
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: netmask
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: Framed-MTU
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: Framed-Protocol
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: routing
*Oct 28 21:44:10: As51 PPP/AAA: Check Attr: service-type
*Oct 28 21:44:10: As51 AAA/AUTHOR/FSM: We can start LCP
*Oct 28 21:44:10: As51 AAA/AUTHOR/LCP: Process Author
*Oct 28 21:44:10: As51 AAA/AUTHOR/LCP: Process Attr: timeout
*Oct 28 21:44:10: AAA/AUTHOR: Processing PerUser AV timeout
*Oct 28 21:44:10: As51 AAA/AUTHOR/LCP: Process Attr: service-type
*Oct 28 21:44:10: As51 PAP: O AUTH-ACK id 1 len 5
*Oct 28 21:44:10: AS_ST_MODEM_INFO(1/50): init rx/tx 26400/40000 current
rx/tx 28800/37333
*Oct 28 21:44:10: AS_ST_MODEM_INFO(1/50): compression 0/None, modulation
12/V90, protocol 4/LAPM
*Oct 28 21:44:10: As51 PPP: Phase is UP
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: FSM authorization not needed
*Oct 28 21:44:10: As51 AAA/AUTHOR/FSM: We can start IPCP
*Oct 28 21:44:10: As51 IPCP: O CONFREQ [Closed] id 1 len 10
*Oct 28 21:44:10: As51 IPCP: Address 192.168.3.21 (0x0306C0A80315)
*Oct 28 21:44:10: As51 PPP: Process pending packets
*Oct 28 21:44:10: RADIUS(0000029C): Using existing nas_port 51
*Oct 28 21:44:10: RADIUS(0000029C): Config NAS IP: 0.0.0.0
*Oct 28 21:44:10: RADIUS(0000029C): sending
*Oct 28 21:44:10: RADIUS/ENCODE: Best Local IP-Address 192.168.3.21 for
Radius-Server 203.210.160.3
*Oct 28 21:44:10: RADIUS(0000029C): Send Accounting-Request to
203.210.160.3:1813 id 21649/200, len 250
*Oct 28 21:44:10: RADIUS: authenticator 00 C6 5E 95 D8 86 C0 03 - 0B E8 99
1A 1E 1C 4E BE
*Oct 28 21:44:10: RADIUS: Acct-Session-Id [44] 10 "000003AF"
*Oct 28 21:44:10: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Oct 28 21:44:10: RADIUS: Vendor, Cisco [26] 32
*Oct 28 21:44:10: RADIUS: Cisco AVpair [1] 26
"connect-progress=Call Up"
*Oct 28 21:44:10: RADIUS: Acct-Authentic [45] 6 RADIUS
[1]
*Oct 28 21:44:10: RADIUS: User-Name [1] 10 "68984212"
*Oct 28 21:44:10: RADIUS: Acct-Status-Type [40] 6 Start
[1]
*Oct 28 21:44:10: RADIUS: Vendor, Cisco [26] 15
*Oct 28 21:44:10: RADIUS: cisco-nas-port [2] 9 "Async51"
*Oct 28 21:44:10: RADIUS: NAS-Port [5] 6 51
*Oct 28 21:44:10: RADIUS: NAS-Port-Type [61] 6 Async
[0]
*Oct 28 21:44:10: RADIUS: Calling-Station-Id [31] 10 "48586127"
*Oct 28 21:44:10: RADIUS: Called-Station-Id [30] 7 "12777"
*Oct 28 21:44:10: RADIUS: Connect-Info [77] 36 "37333/28800
V90/LAPM (40000/26400)"
*Oct 28 21:44:10: RADIUS: Class [25] 62
*Oct 28 21:44:10: RADIUS: 53 42 52 2D 43 4C 20 44 4E 3D 22 36 38 39 38 34
[SBR-CL DN="68984]
*Oct 28 21:44:10: RADIUS: 32 31 32 22 20 41 54 3D 22 32 30 30 22 20 49 50
[212" AT="200" IP]
*Oct 28 21:44:10: RADIUS: 3D 22 31 39 32 2E 31 36 38 2E 33 2E 32 33 33 22
[="192.168.3.233"]
*Oct 28 21:44:10: RADIUS: 20 53 49 3D 22 38 36 31 37 37 22 00
[ SI="86177"?]
*Oct 28 21:44:10: RADIUS: Service-Type [6] 6 Framed
[2]
*Oct 28 21:44:10: RADIUS: NAS-IP-Address [4] 6 192.168.3.21
*Oct 28 21:44:10: RADIUS: Acct-Delay-Time [41] 6 0
*Oct 28 21:44:10: RADIUS: Received from id 21649/200 203.210.160.3:1813,
Accounting-response, len 20
*Oct 28 21:44:10: RADIUS: authenticator 39 D7 3C D4 5D CF 7D EE - 61 4F E6
DD 40 79 39 6A
*Oct 28 21:44:10: As51 IPCP: I CONFREQ [REQsent] id 1 len 40
*Oct 28 21:44:10: As51 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
*Oct 28 21:44:10: As51 IPCP: Address 0.0.0.0 (0x030600000000)
*Oct 28 21:44:10: As51 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
*Oct 28 21:44:10: As51 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
*Oct 28 21:44:10: As51 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
*Oct 28 21:44:10: As51 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
*Oct 28 21:44:10: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0, we want
192.168.3.246
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Processing AV addr
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Processing AV netmask
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Processing AV routing
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Set routing to FALSE
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Authorization succeeded
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want
192.168.3.233
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: no author-info for primary dns
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: no author-info for primary wins
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: no author-info for seconday dns
*Oct 28 21:44:10: As51 AAA/AUTHOR/IPCP: no author-info for seconday wins
*Oct 28 21:44:10: As51 IPCP: O CONFREJ [REQsent] id 1 len 22
*Oct 28 21:44:10: As51 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
*Oct 28 21:44:10: As51 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
*Oct 28 21:44:10: As51 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
*Oct 28 21:44:10: CT: ppp start: hndl=510
*Oct 28 21:44:10: As51 CCP: I CONFREQ [Not negotiated] id 1 len 15
*Oct 28 21:44:10: As51 CCP: MS-PPC supported bits 0x00000001
(0x120600000001)
*Oct 28 21:44:10: As51 CCP: Stacker history 1 check mode EXTENDED
(0x1105000104)
*Oct 28 21:44:10: As51 LCP: O PROTREJ [Open] id 42 len 21 protocol CCP
*Oct 28 21:44:10: As51 LCP: (0x80FD0101000F12060000000111050001)
*Oct 28 21:44:10: As51 LCP: (0x04)
*Oct 28 21:44:10: As51 IPCP: I CONFACK [REQsent] id 1 len 10
*Oct 28 21:44:10: As51 IPCP: Address 192.168.3.21 (0x0306C0A80315)
*Oct 28 21:44:12: As51 IPCP: TIMEout: State ACKrcvd
*Oct 28 21:44:12: As51 IPCP: O CONFREQ [ACKrcvd] id 2 len 10
*Oct 28 21:44:12: As51 IPCP: Address 192.168.3.21 (0x0306C0A80315)
*Oct 28 21:44:13: As51 IPCP: I CONFACK [REQsent] id 2 len 10
*Oct 28 21:44:13: As51 IPCP: Address 192.168.3.21 (0x0306C0A80315)
*Oct 28 21:44:13: TTY40: cleanup pending. Delaying DTR
*Oct 28 21:44:13: TTY40: cleanup pending. Delaying DTR
*Oct 28 21:44:13: As51 IPCP: I CONFREQ [ACKrcvd] id 2 len 34
*Oct 28 21:44:13: As51 IPCP: Address 0.0.0.0 (0x030600000000)
*Oct 28 21:44:13: As51 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
*Oct 28 21:44:13: As51 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
*Oct 28 21:44:13: As51 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
*Oct 28 21:44:13: As51 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
*Oct 28 21:44:13: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for primary dns
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for primary wins
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for seconday dns
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for seconday wins
*Oct 28 21:44:13: As51 IPCP: O CONFREJ [ACKrcvd] id 2 len 16
*Oct 28 21:44:13: As51 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
*Oct 28 21:44:13: As51 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
*Oct 28 21:44:13: CT: ppp start: hndl=510
*Oct 28 21:44:13: As51 IPCP: I CONFREQ [ACKrcvd] id 3 len 22
*Oct 28 21:44:13: As51 IPCP: Address 0.0.0.0 (0x030600000000)
*Oct 28 21:44:13: As51 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
*Oct 28 21:44:13: As51 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
*Oct 28 21:44:13: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for primary dns
*Oct 28 21:44:13: As51 AAA/AUTHOR/IPCP: no author-info for seconday dns
*Oct 28 21:44:13: As51 IPCP: O CONFNAK [ACKrcvd] id 3 len 22
*Oct 28 21:44:13: As51 IPCP: Address 192.168.3.233 (0x0306C0A803E9)
*Oct 28 21:44:14: As51 IPCP: PrimaryDNS 203.210.160.100 (0x8106CBD2A064)
*Oct 28 21:44:14: As51 IPCP: SecondaryDNS 203.162.0.11 (0x8306CBA2000B)
*Oct 28 21:44:14: CT: ppp start: hndl=510
*Oct 28 21:44:14: from Trunk(0): (1/11): Tx IDLE (ABCD=1001)
*Oct 28 21:44:14: As51 IPCP: I CONFREQ [ACKrcvd] id 4 len 22
*Oct 28 21:44:14: As51 IPCP: Address 192.168.3.233 (0x0306C0A803E9)
*Oct 28 21:44:14: As51 IPCP: PrimaryDNS 203.210.160.100 (0x8106CBD2A064)
*Oct 28 21:44:14: As51 IPCP: SecondaryDNS 203.162.0.11 (0x8306CBA2000B)
*Oct 28 21:44:14: As51 PPP/CT: pppstart hndl 510
*Oct 28 21:44:14: As51 AAA/AUTHOR/IPCP: no author-info for primary dns
*Oct 28 21:44:14: As51 AAA/AUTHOR/IPCP: no author-info for seconday dns
*Oct 28 21:44:14: As51 IPCP: O CONFACK [ACKrcvd] id 4 len 22
*Oct 28 21:44:14: As51 IPCP: Address 192.168.3.233 (0x0306C0A803E9)
*Oct 28 21:44:14: As51 IPCP: PrimaryDNS 203.210.160.100 (0x8106CBD2A064)
*Oct 28 21:44:14: As51 IPCP: SecondaryDNS 203.162.0.11 (0x8306CBA2000B)
*Oct 28 21:44:14: As51 IPCP: State is Open
*Oct 28 21:44:14: CT: ppp start: hndl=510
*Oct 28 21:44:14: As51 PPP/CT: pppserviceup hndl 510
*Oct 28 21:44:14: As51 PPP/CT: pppserviceup user 68984212 addr 192.168.3.233
mask 0.0.0.0
*Oct 28 21:44:14: As51 IPCP: Install route to 192.168.3.233
*Oct 28 21:44:14: As51 IPCP: Add link info for cef entry 192.168.3.233
*Oct 28 21:44:14: CT: user valid: hndl=510, user=68984212
*Oct 28 21:46:02: Mica Modem(1/50): State Transition to Steady State
Retraining
*Oct 28 21:46:19: Mica Modem(1/50): State Transition to Steady State
*Oct 28 21:47:12: Mica Modem(1/50): State Transition to Steady State
Retraining
*Oct 28 21:47:54: Mica Modem(1/50): State Transition to Steady State
*Oct 28 21:48:49: Mica Modem(1/50): State Transition to Steady State
Retraining
*Oct 28 21:48:56: Mica Modem(1/50): State Transition to Steady State
*Oct 28 21:48:57: Mica Modem(1/50): State Transition to Steady State
Retraining
*Oct 28 21:49:17: Mica Modem(1/50): Link Terminate(0x6)
*Oct 28 21:49:17: CSM(1/50): Enter csm_enter_disconnecting_state
*Oct 28 21:49:17: csm_call_prog_disc_reason - DATA
*Oct 28 21:49:17: tty=0x615159C8 num=51 port=50 slot=1 shelf=0 type=2 name=
idb=0x6196FB70
*Oct 28 21:49:17: In actv_c_proc_message,
access type CPM_REMOVE_DISC_CALL,
call type CPM_CT1_ANALOG:
Removed a disconnected CT1 analog call
CC-Slot#0, DSX1-Ctrlr#0, DS0-Timeslot#31
*Oct 28 21:49:17: Mdm-Slot#1, Mdm-Port#50, TTY#51
*Oct 28 21:49:17: CT: call disconnect: hndl=510,
disc(id=0x3(CSM), code=0xE, text=Failed to detect carrier), Q.xxx=0
*Oct 28 21:49:17: CT: Successfully deleted active call-record entry hndl=510
from table.
*Oct 28 21:49:17: CT: TCP entry (hndl=510) does not exists, no need to
remove from AVL
*Oct 28 21:49:17: CT: Modem entry (hndl=510) does not exists, no need to
remove from AVL
*Oct 28 21:49:17: CT: got tx(7250726)/rx(1883400) counts for actv call
(hndl=510, cat=3, type=4)
*Oct 28 21:49:17: CT: calc'd tx(7250726)/rx(1883400) deltas for actv call
(hndl=510)
*Oct 28 21:49:17: CT: storing disc info (id=0x3, code=0xE) in hist node
(indx=483, hndl=510)
*Oct 28 21:49:17: CT: Successfully inserted history call-record entry
hndl=510 into table.
*Oct 28 21:49:17: CT: actv-->hist ok: node (hndl=510) is now (or already
was) in history table
*Oct 28 21:49:17: AS_ST_MODEM_INFO(1/50): init rx/tx 19200/42666 current
rx/tx 21600/21600
*Oct 28 21:49:17: AS_ST_MODEM_INFO(1/50): compression 0/None, modulation
10/V34+, protocol 4/LAPM
*Oct 28 21:49:17: RADIUS(0000029C): Using existing nas_port 51
*Oct 28 21:49:17: RADIUS(0000029C): Config NAS IP: 0.0.0.0
*Oct 28 21:49:17: RADIUS(0000029C): sending
*Oct 28 21:49:17: RADIUS/ENCODE: Best Local IP-Address 192.168.3.21 for
Radius-Server 203.210.160.3
*Oct 28 21:49:17: RADIUS(0000029C): Send Accounting-Request to
203.210.160.3:1813 id 21649/223, len 323
*Oct 28 21:49:17: RADIUS: authenticator 2F 75 C9 0E 59 AA 2F D3 - 69 82 D3
A0 D6 93 BC E6
*Oct 28 21:49:17: RADIUS: Acct-Session-Id [44] 10 "000003AF"
*Oct 28 21:49:17: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Oct 28 21:49:17: RADIUS: Framed-IP-Address [8] 6 192.168.3.233
*Oct 28 21:49:17: RADIUS: Acct-Authentic [45] 6 RADIUS
[1]
*Oct 28 21:49:17: RADIUS: Acct-Terminate-Cause[49] 6 lost-carrier
[2]
*Oct 28 21:49:17: RADIUS: Vendor, Cisco [26] 33
*Oct 28 21:49:17: RADIUS: Cisco AVpair [1] 27 "disc-cause-ext=No
Carrier"
*Oct 28 21:49:17: RADIUS: Vendor, Cisco [26] 35
*Oct 28 21:49:17: RADIUS: Cisco AVpair [1] 29
"connect-progress=LAN Ses Up"
*Oct 28 21:49:17: RADIUS: Acct-Session-Time [46] 6 307
*Oct 28 21:49:17: RADIUS: Acct-Input-Octets [42] 6 33258
*Oct 28 21:49:17: RADIUS: Acct-Output-Octets [43] 6 194868
*Oct 28 21:49:17: RADIUS: Acct-Input-Packets [47] 6 505
*Oct 28 21:49:17: RADIUS: Acct-Output-Packets [48] 6 511
*Oct 28 21:49:17: RADIUS: User-Name [1] 10 "68984212"
*Oct 28 21:49:17: RADIUS: Acct-Status-Type [40] 6 Stop
[2]
*Oct 28 21:49:17: RADIUS: Vendor, Cisco [26] 15
*Oct 28 21:49:17: RADIUS: cisco-nas-port [2] 9 "Async51"
*Oct 28 21:49:17: RADIUS: NAS-Port [5] 6 51
*Oct 28 21:49:17: RADIUS: NAS-Port-Type [61] 6 Async
[0]
*Oct 28 21:49:17: RADIUS: Calling-Station-Id [31] 10 "48586127"
*Oct 28 21:49:17: RADIUS: Called-Station-Id [30] 7 "12777"
*Oct 28 21:49:17: RADIUS: Connect-Info [77] 31 "21600 V34+/LAPM
(42666/19200)"
*Oct 28 21:49:17: RADIUS: Class [25] 62
*Oct 28 21:49:17: RADIUS: 53 42 52 2D 43 4C 20 44 4E 3D 22 36 38 39 38 34
[SBR-CL DN="68984]
*Oct 28 21:49:17: RADIUS: 32 31 32 22 20 41 54 3D 22 32 30 30 22 20 49 50
[212" AT="200" IP]
*Oct 28 21:49:17: RADIUS: 3D 22 31 39 32 2E 31 36 38 2E 33 2E 32 33 33 22
[="192.168.3.233"]
*Oct 28 21:49:17: RADIUS: 20 53 49 3D 22 38 36 31 37 37 22 00
[ SI="86177"?]
*Oct 28 21:49:17: RADIUS: Service-Type [6] 6 Framed
[2]
*Oct 28 21:49:17: RADIUS: NAS-IP-Address [4] 6 192.168.3.21
*Oct 28 21:49:17: RADIUS: Acct-Delay-Time [41] 6 0
*Oct 28 21:49:17: Mica Modem(1/50): State Transition to Terminating
*Oct 28 21:49:17: TTY51: DSR was dropped
*Oct 28 21:49:17: tty51: Modem: READY->(unknown)
*Oct 28 21:49:17: Mica Modem(1/50): State Transition to Idle
*Oct 28 21:49:17: Mica Modem(1/50): Went onhook
*Oct 28 21:49:17: CSM_PROC_IC8_OC8_DISCONNECTING: CSM_EVENT_MODEM_ONHOOK at
slot 1, port 50
*Oct 28 21:49:17: CSM(1/50): Enter csm_enter_idle_state
*Oct 28 21:49:17: csm_call_prog_disc_reason - DATA
*Oct 28 21:49:17: tty=0x615159C8 num=51 port=50 slot=1 shelf=0 type=2 name=
idb=0x6196FB70
*Oct 28 21:49:17: R2 Incoming Modem(1/50): DSX (E1 0:30): STATE: R2_IN_IDLE
R2 Got Event R2_STOP
*Oct 28 21:49:17: VDEV_DEALLOCATE: slot 1 and port 50 is deallocated
*Oct 28 21:49:17: TTY51: dropping DTR, hanging up
*Oct 28 21:49:17: TTY51: Async Int reset: Dropping DTR
*Oct 28 21:49:17: tty51: Modem: HANGUP->(unknown)
*Oct 28 21:49:17: TTY51: cleanup pending. Delaying DTR
*Oct 28 21:49:17: RADIUS: Received from id 21649/223 203.210.160.3:1813,
Accounting-response, len 20
*Oct 28 21:49:17: RADIUS: authenticator C7 87 6E C7 72 74 50 1A - D3 27 06
FC FD AF F9 C7
*Oct 28 21:49:17: Mica Modem(1/50): State Transition to Terminating
*Oct 28 21:49:18: Mica Modem(1/50): State Transition to Idle
*Oct 28 21:49:19.974: %LINK-5-CHANGED: Interface Async51, changed state to
reset
*Oct 28 21:49:19: As51 PPP: Sending Acct Event[Down] id[29C]
*Oct 28 21:49:19: As51 IPCP: Remove link info for cef entry 192.168.3.233
*Oct 28 21:49:19: As51 IPCP: State is Closed
*Oct 28 21:49:19: As51 PPP: Phase is TERMINATING
*Oct 28 21:49:19: As51 LCP: State is Closed
*Oct 28 21:49:19: As51 PPP: Phase is DOWN
*Oct 28 21:49:22: Async51: allowing modem_process to continue hangup
*Oct 28 21:49:23: TTY51: restoring DTR
*Oct 28 21:49:23: TTY51: autoconfigure probe started
*Oct 28 21:49:23.530: %CALLTRKR-6-CALL_RECORD: ct_hndl=510, service=PPP,
origin=Answer, category=Modem, DS0 slot/port/ds1/chan=0/0/0/30,
called=12777, calling=48586127, resource slot/port=1/50, userid=68984212,
ip=192.168.3.233, mask=0.0.0.0, account id=943, setup=10/28/2004 21:43:55,
conn=0.01, phys=15.52, service=20.15, authen=20.15, init-rx/tx
b-rate=19200/42666, rx/tx chars=1883400/7250726, time=323.81, disc
subsys=CSM, disc code=0xE, disc text=Failed to detect carrier
*Oct 28 21:49:24.982: %LINK-3-UPDOWN: Interface Async51, changed state to
down
*Oct 28 21:49:27.502: %LINEPROTO-5-UPDOWN: Line protocol on Interface
Async31, changed state to down
*Oct 28 21:49:27: CT: call disconnect: hndl=510,
disc(id=0x5(Modem Drvrs), code=0xDF06, text= Tx (host to line) data
flushing - OK/Requested by host/network indicated disconnect), Q.xxx=0
*Oct 28 21:49:27: CT: actv-->hist ok: node (hndl=510) is now (or already
was) in history table
*Oct 28 21:49:27: CT: dsp byte count: hndl=510, tx/rx=194940/34379
And the sampe line shapes for such a call
Modem(1/3) Operational-Status:
Parameter #0 Disconnect Reason Info: (0xDF06)
Type (=6 ): Tx (host to line) data flushing - OK
Class (=31): Requested by host
Reason (=6 ): network indicated disconnect
Parameter #1 Connect Protocol: LAP-M
Parameter #2 Compression: None
Parameter #3 EC Retransmission Count: 24
Parameter #4 Self Test Error Count: 0
Parameter #5 Call Timer: 211 secs
Parameter #6 Total Retrains: 6
Parameter #7 Sq Value: 1
Parameter #8 Connected Standard: V.90
Parameter #9 TX,RX Bit Rate: 53333, 28800
Parameter #11 TX,RX Symbol Rate: 8000, 3200
Parameter #13 TX,RX Carrier Frequency: 0, 1920
Parameter #15 TX,RX Trellis Coding: 0, 16
Parameter #16 TX,RX Preemphasis Index: 20, 0
Parameter #17 TX,RX Constellation Shaping: Off, Off
Parameter #18 TX,RX Nonlinear Encoding: Off, Off
Parameter #19 TX,RX Precoding: Off, Off
Parameter #20 TX,RX Xmit Level Reduction: 0, 2 dBm
Parameter #21 Signal Noise Ratio: 40 dB
Parameter #22 Receive Level: -18 dBm
Parameter #23 Frequency Offset: -1 Hz
Parameter #24 Phase Jitter Frequency: 0 Hz
Parameter #25 Phase Jitter Level: 0 degrees
Parameter #26 Far End Echo Level: -30 dBm
Parameter #27 Phase Roll: 0 degrees
Parameter #28 Round Trip Delay: 4 msecs
Parameter #30 Characters transmitted, received: 65286, 57234
Parameter #32 General Portware Information: 20
Parameter #33 PPP/SLIP packets transmitted, received: 140, 747
Parameter #35 PPP/SLIP packets received (BAD/ABORTED): 0
Parameter #36 EC packets transmitted, received OK: 401, 738
Parameter #38 Moving Average of EC packets (Received BAD/ABORTED): 24
Parameter #39 Robbed Bit Signalling (RBS) pattern: 0
Parameter #40 Digital Pad: None, Digital Pad Compensation: Enabled
Parameter #42 SS7/COT Status: 0
Parameter #43 V110/PIAFS frames received bad: 0
Parameter #44 V110/PIAFS frames received good: 0
Parameter #45 V110/PIAFS frames transmitted: 0
Parameter #46 V110/PIAFS sync lost: 0
Parameter #93 PIAFS RTF: 0
Parameter #120 Total Speedshifts: 0
Parameter #108 Total MOH Time: 0 secs
Parameter #109 Current MOH Time: 0 secs
Parameter #105 MOH Status: Modem is Not on Hold
Parameter #106 MOH Count: 0
Parameter #107 MOH Request Count: 0
Parameter #110 Retrains due to Call Waiting: 0
Parameter #114 DC Encoder,Decoder State: stat not supported/stat not
supported
Parameter #115 DC TX,RX Compression Ratio: 0.0:1, 0.0:1
Parameter #117 DC TX,RX Dictionary Reset Count: 0, 0
Parameter #119 Diagnostic Code: 00 00 00 00 00 00 00 00
Line Shape:
.........................*
................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
.................................*
................................*
................................*
............................*
....................*
-------------- next part --------------
An HTML attachment was scrubbed...
URL: https://puck.nether.net/pipermail/cisco-nas/attachments/20041029/092da265/attachment-0001.html
More information about the cisco-nas
mailing list