[c-nsp] PPPoA DSL up/up, no traffic

Tue Oct 2 17:01:15 EDT 2007

iirc DSL line scrambling should be negotiated between the DSL interfaces.
so if it is on or off it shouldn't matter.

the virtual access interface will remain down untill PPP LCP (Line Control
Protocol) is negotiated.  since you are not getting any incoming PPP packets,
LCP negotiation never starts.  hence, your virtual access interface is
up (phyiscal interface it's bound to is up), down (LCP not yet open, hence
status is down).

i think what you need to do is find out from your provider how your line
is provisioned (which ATM VC, which encap, and if they are doing PPPoA
with snap or mux encap or 1483 bridging).  this will allow you to 
configure the router appropriately.

one way to guss some of this is to see if your provider gave you a free
DSL modem with your DSL link.  based on it's capabilities and it's
config you could guess with reasonable accuracies the answers to some
of the above questions.

cheers
.siva

On Tue, 2 Oct 2007, Adam Greene wrote:

> Hi all,
>
> I appreciate the feedback.
>
> I tried these commands, but no dice:
>
> pvc 0/35
> encapsulation aal5mux ppp dialer
> dialer pool-member 1
>
> The router doesn't seem to accept the "atm route-bridge ip" command. I tried 
> on the atm interface and the pvc.
>
> I couldn't find a place to enter a "scrambling" or "no scrambling" command 
> either, unfortunately (someone suggested this off-list).
>
> I tried deleting and recreating the pvc on the cpe end, with no positive 
> results.
>
> I will contact the ISP and see if they can recreate the pvc on their end.
>
> One note: this probably doesn't mean anything, but I see interface 
> Virtual-Access 2 gets bound to Dialer1, but shows up/down, with lots of 
> outbound packets but no inbound packets. By contrast, int Virtual-Access 1 is 
> up/up but not bound to anything and is not passing traffic. I wonder if 
> that's relevant at all.
>
> Finally, here's some debug ppp neg and debug atm events output during the 
> setup phase. It appears the Vi2 LCP step is what is failing.
>
> *Oct  2 20:46:12.891: ATM0/0/0 dslsar_1a_reset: PLIM type is 18, Rate is 
> 832Mbps
> *Oct  2 20:46:12.891: ATM0/0/0 dslsar_1a_shutdown: state=4
> *Oct  2 20:46:12.891: dslsar disable ATM0/0/0
> *Oct  2 20:46:12.895: DSL: SET: [DMTDSL_STOP -> DMTDSL_INIT]
> *Oct  2 20:46:12.895: Resetting ATM0/0/0
> *Oct  2 20:46:12.895:  dslsar_1a_config(ATM0/0/0)
> *Oct  2 20:46:12.895:  dslsar_1a_enable(ATM0/0/0)
> *Oct  2 20:46:12.895: ATM0/0/0: dslsar_init
> *Oct  2 20:46:12.899: ATM0/0/0 dslsar_MatchSARTxToLineSpeed(): usbw 832, 
> clkPerCell 18004 prev_clkPerCell 9702
> *Oct  2 20:46:12.899: ATM0/0/0 dslsar_MatchSARTxToLineSpeed(): Changing line 
> speed from fast to slow
> *Oct  2 20:46:13.015: ATM0/0/0 dslsar_update_us_bandwidth(): upstream bw =832 
> Kbps
> *Oct  2 20:46:13.535: (ATM0/0/0)1a_enable: delay activation of vcd=2, 
> vc=0x62EABDBC
> *Oct  2 20:46:13.539: DSL: SM: [DMTDSL_STOP -> DMTDSL_INIT]
> *Oct  2 20:46:13.539: DSL: SM: [DMTDSL_INIT -> DMTDSL_DLOAD_1]
> *Oct  2 20:46:13.539: DSL: Downloading ASW_init_3_8_131.bin
> *Oct  2 20:46:13.547: DSL:(ATM0/0/0) Downloaded 5 blocks... Finished!
> *Oct  2 20:46:13.547: DSL(ATM0/0/0): Sent command 0x14
> *Oct  2 20:46:14.891: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to 
> down
> *Oct  2 20:46:14.891:  dslsar_atm_lineaction(ATM0/0/0): state=0
> *Oct  2 20:46:14.891:  dslsar_atm_lineaction: REG_INVOKE: line down
> *Oct  2 20:46:17.455: DSL: Received response: 0x80
> *Oct  2 20:46:17.455: DSL: SM: [DMTDSL_DLOAD_1 -> DMTDSL_DLOAD_2]
> *Oct  2 20:46:17.539: DSL: Downloading ASW_R3_8_131.bin
> *Oct  2 20:46:17.687: DSL(ATM0/0/0): Downloaded 100 blocks
> *Oct  2 20:46:17.835: DSL(ATM0/0/0): Downloaded 200 blocks
> *Oct  2 20:46:17.979: DSL(ATM0/0/0): Downloaded 300 blocks
> *Oct  2 20:46:18.127: DSL(ATM0/0/0): Downloaded 400 blocks
> *Oct  2 20:46:18.275: DSL(ATM0/0/0): Downloaded 500 blocks
> *Oct  2 20:46:18.419: DSL(ATM0/0/0): Downloaded 600 blocks
> *Oct  2 20:46:18.571: DSL(ATM0/0/0): Downloaded 700 blocks
> *Oct  2 20:46:18.715: DSL(ATM0/0/0): Downloaded 800 blocks
> *Oct  2 20:46:18.863: DSL(ATM0/0/0): Downloaded 900 blocks
> *Oct  2 20:46:19.011: DSL(ATM0/0/0): Downloaded 1000 blocks
> *Oct  2 20:46:19.155: DSL(ATM0/0/0): Downloaded 1100 blocks
> *Oct  2 20:46:19.303: DSL(ATM0/0/0): Downloaded 1200 blocks
> *Oct  2 20:46:19.451: DSL(ATM0/0/0): Downloaded 1300 blocks
> *Oct  2 20:46:19.475: DSL:(ATM0/0/0) Downloaded 1317 blocks... Finished!
> *Oct  2 20:46:19.475: DSL(ATM0/0/0): Sent command 0x14
> *Oct  2 20:46:21.475: changed current state to do open!!
> *Oct  2 20:46:21.475: DSL: SM: [DMTDSL_DLOAD_2 -> DMTDSL_DO_OPEN]
> *Oct  2 20:46:21.475: DSL: Send ADSL_OPEN command.
> *Oct  2 20:46:21.475: DSL(ATM0/0/0): Using subfunction 0x15
> *Oct  2 20:46:21.479: DSL(ATM0/0/0): Sent command 0x3
> *Oct  2 20:46:23.979: DSL(ATM0/0/0): 1: Modem state = 0x8
> *Oct  2 20:46:26.479: DSL(ATM0/0/0): 2: Modem state = 0x8
> *Oct  2 20:46:28.979: DSL(ATM0/0/0): 3: Modem state = 0x8
> *Oct  2 20:46:31.479: DSL(ATM0/0/0): 4: Modem state = 0x10
> *Oct  2 20:46:33.979: DSL(ATM0/0/0): 5: Modem state = 0x10
> *Oct  2 20:46:36.479: DSL(ATM0/0/0): 6: Modem state = 0x10
> *Oct  2 20:46:37.607: DSL: Received response: 0x24
> *Oct  2 20:46:37.607: DSL: Showtime!
> *Oct  2 20:46:37.607: DSL(ATM0/0/0): Sent command 0x11
> *Oct  2 20:46:37.611: DSL: Received response: 0x61
> *Oct  2 20:46:37.611: DSL: Read firmware revision 0x1A04
> *Oct  2 20:46:37.611: DSL(ATM0/0/0): Sent command 0x31
> *Oct  2 20:46:37.615: DSL: Received response: 0x12
> *Oct  2 20:46:37.615: DSL(ATM0/0/0): operation mode 0x0002
> *Oct  2 20:46:37.615: DSL(ATM0/0/0): Sent command 0x33
> *Oct  2 20:46:37.619: DSL: Received response: 0x16
> *Oct  2 20:46:37.619: DSL(ATM0/0/0): Far End ITU Country Code 0x0F
> *Oct  2 20:46:37.619: DSL: Far End ITU Vendor ID ALCB
> *Oct  2 20:46:37.619: DSL: Far End ITU Vendor ID Specific 0x0000
> *Oct  2 20:46:37.623: DSL: Far End ITU Vendor STD Number 0x0001
> *Oct  2 20:46:37.623: DSL(ATM0/0/0): Sent command 0x32
> *Oct  2 20:46:37.627: DSL: Received response: 0x14
> *Oct  2 20:46:37.627: DSL(ATM0/0/0): Near End ITU Country Code 0x00
> *Oct  2 20:46:37.627: DSL: Near End ITU Vendor ID ALCB
> *Oct  2 20:46:37.627: DSL: Near End ITU Vendor ID Specific 0x0000
> *Oct  2 20:46:37.627: DSL: Near End ITU Vendor STD Number 0x0001
> *Oct  2 20:46:37.627: ATM0/0/0 dslsar_MatchSARTxToLineSpeed(): usbw 832, 
> clkPerCell 18004 prev_clkPerCell 18004
> *Oct  2 20:46:37.627: ATM0/0/0 dslsar_update_us_bandwidth(): upstream bw =832 
> Kbps
> *Oct  2 20:46:37.627: DSL: SM: [DMTDSL_DO_OPEN -> DMTDSL_SHOWTIME]
> *Oct  2 20:46:39.207:  dslsar_periodic: ENABLING DSLSAR
> *Oct  2 20:46:39.207: (ATM0/0/0)1a_enable: delay activation of vcd=2, 
> vc=0x62EABDBC
> *Oct  2 20:46:40.543: dslsar enable ATM0/0/0
> *Oct  2 20:46:40.543: ATM0/0/0: dslsar_bringup_interface: Interface and 
> atm_db flags are UP
> *Oct  2 20:46:42.543: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to up
> *Oct  2 20:46:42.543:  dslsar_atm_lineaction(ATM0/0/0): state=4
> *Oct  2 20:46:42.543:  dslsar_atm_lineaction: REG_INVOKE: line up
> *Oct  2 20:46:45.543: %LINEPROTO-5-UPDOWN: Line protocol on Interface 
> ATM0/0/0, changed state to up
> *Oct  2 20:46:48.031: dslssar_init_tcq: Initializing TCQ
> *Oct  2 20:46:48.031: dslsar_init_txring_params: default tx-ring setting is 
> selected for vpi/vci = 0/35
> *Oct  2 20:46:48.031: ATM0/0/0:dslsar_init_tx_chan_desc_per_vc, vcd = 2, addr 
> = 0x00011080, size = 64
> *Oct  2 20:46:48.031: ATM0/0/0 dslsar_vc_setup: vcd 2
> *Oct  2 20:46:48.031: CONFIGURING(ATM0/0/0) VC 2 (0/35) IN TX SCHEDULE TABLE 
> SET 1
> *Oct  2 20:46:48.031: (ATM0/0/0)Forcing Peakrate and Avgrate to: 832
> *Oct  2 20:46:48.031: (ATM0/0/0)Requested QoS: Peakrate = 832, Avgrate = 832, 
> Burstsize =0
> *Oct  2 20:46:48.031: (ATM0/0/0)Configuring VC 2:  slot 0 in TST 5
> *Oct  2 20:46:48.031: (ATM0/0/0) SUCCESSFUL CONFIGURATION OF  VC 2 (0/35), 
> QOS Type 4
> *Oct  2 20:46:48.031: dslsar_setup_cos(ATM0/0/0): vc:2 wred_name:- max_q:0
> *Oct  2 20:46:48.031:   ATM0/0/0: vcd = 2, max_tx_time = 2578
> *Oct  2 20:46:48.031: ATM0/0/0 check_lockup: scc = 0, output_qcount = 0, 
> head:(s)5, 0, addr = (s)0x0, 0x0, count (s)69587, 69590
> *Oct  2 20:46:48.031: ATM0/0/0 check_lockup: scc = 1, output_qcount = 0, 
> head:(s)55, 52, addr = (s)0x0, 0x62D20674, count (s)658, 715
> *Oct  2 20:46:49.031: %LINK-3-UPDOWN: Interface Virtual-Access2, changed 
> state to up
> *Oct  2 20:46:49.031: Vi2 PPP: Using dialer call direction
> *Oct  2 20:46:49.031: Vi2 PPP: Treating connection as a callout
> *Oct  2 20:46:49.031: Vi2 PPP: Session handle[1A000014] Session id[13]
> *Oct  2 20:46:49.031: Vi2 PPP: Phase is ESTABLISHING, Active Open
> *Oct  2 20:46:49.031: Vi2 PPP: No remote authentication for call-out
> *Oct  2 20:46:49.031: Vi2 LCP: O CONFREQ [Closed] id 40 len 10
> *Oct  2 20:46:49.031: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:51.031: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:46:51.031: Vi2 LCP: O CONFREQ [REQsent] id 41 len 10
> *Oct  2 20:46:51.031: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:53.047: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:46:53.047: Vi2 LCP: O CONFREQ [REQsent] id 42 len 10
> *Oct  2 20:46:53.047: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:53.047: dslsar_tx_status_ind, last_tsi_idx = 0, tsi_tcq_map_idx 
> = 3
> *Oct  2 20:46:55.063: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:46:55.063: Vi2 LCP: O CONFREQ [REQsent] id 43 len 10
> *Oct  2 20:46:55.063: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:57.079: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:46:57.079: Vi2 LCP: O CONFREQ [REQsent] id 44 len 10
> *Oct  2 20:46:57.079: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:57.991: ATM0/0/0 check_lockup: scc = 0, output_qcount = 0, 
> head:(s)0, 5, addr = (s)0x0, 0x0, count (s)69590, 69595
> *Oct  2 20:46:57.991: ATM0/0/0 check_lockup: scc = 1, output_qcount = 0, 
> head:(s)52, 55,
> addr = (s)0x62D20674, 0x0, count (s)715, 715
> *Oct  2 20:46:59.095: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:46:59.095: Vi2 LCP: O CONFREQ [REQsent] id 45 len 10
> *Oct  2 20:46:59.095: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:46:59.095: dslsar_tx_status_ind, last_tsi_idx = 3, tsi_tcq_map_idx 
> = 7
> *Oct  2 20:47:01.111: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:47:01.111: Vi2 LCP: O CONFREQ [REQsent] id 46 len 10
> *Oct  2 20:47:01.111: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:47:03.127: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:47:03.127: Vi2 LCP: O CONFREQ [REQsent] id 47 len 10
> *Oct  2 20:47:03.127: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:47:05.143: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:47:05.143: Vi2 LCP: O CONFREQ [REQsent] id 48 len 10
> *Oct  2 20:47:05.143: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:47:05.143: dslsar_tx_status_ind, last_tsi_idx = 7, tsi_tcq_map_idx 
> = 11
> *Oct  2 20:47:07.159: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:47:07.159: Vi2 LCP: O CONFREQ [REQsent] id 49 len 10
> *Oct  2 20:47:07.159: Vi2 LCP:    MagicNumber 0x30B4140C (0x050630B4140C)
> *Oct  2 20:47:07.971: ATM0/0/0 check_lockup: scc = 0, output_qcount = 0, 
> head:(s)5, 10, addr = (s)0x0, 0x0, count (s)69595, 69600
> *Oct  2 20:47:07.971: ATM0/0/0 check_lockup: scc = 1, output_qcount = 0, 
> head:(s)55, 55, addr = (s)0x0, 0x0, count (s)715, 715
> *Oct  2 20:47:09.175: Vi2 LCP: TIMEout: State REQsent
> *Oct  2 20:47:09.175: Vi2 LCP: State is Listen
>
> thanks,
> Adam 
>
>