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

Tue Oct 2 16:54:46 EDT 2007

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 