Re: [nsp] Weird PPP problem with NM-8AM in 2610

From: Josh Duffek (jduffek@cisco.com)
Date: Tue Jun 11 2002 - 13:56:34 EDT


[adding in cisco-nas]

Looks like: CSCdi75794 - V.34 without Error Correction fails at 2400 bps

Not sure what to do about it though...

Josh

----- Original Message -----
From: "Hailstone, Simon" <SHailstone@ndsuk.com>
To: <cisco-nsp@puck.nether.net>
Sent: Tuesday, June 11, 2002 10:56 AM
Subject: [nsp] Weird PPP problem with NM-8AM in 2610

> Hi All
>
> I am having a strange problem with a 2610 running 12.0(2a)T1 with
> a NM-8AM, MCOM firmware(s) boot 1.1.5 MIMIC 1.3.3 Modem 2.3.11 DSP 0.0.2
>
> I am doing PPP dialup with CHAP for a variety of different devices,
> including several embedded devices.
>
> This is working pretty much fine except for a problem that only occurs
> at v22bis. With LAPM and V42bis, I can connect at 2400 perfectly, and
> LCP negotiation occurs correctly, IPCP etc. Absolutely fine.
>
> However, if I disable LAPM I can still "CONNECT" but LCP doesn't
> complete correctly...
>
> Anyone ever seen a similar problem?
> A somewhat verbose bebug log follows below.
>
> Thanks in advance,
> Simon Hailstone
>
> PS I do have a good reason for wanting to do v22bis
> without LAPM and v42bis!
>
> ======================================================================
>
> 19:29:06: Modem 1/7 Mcom: in modem state 'Dialing/Answering'
> 19:29:06: Modem 1/7 Mcom: in modem state 'Incoming ring'
> 19:29:09: Modem 1/7 Mcom: in modem state 'Waiting for Carrier'
> 19:29:14: Modem 1/7 Mcom: in modem state 'Connected'
> 19:29:15: Modem 1/7 Mcom: CONNECT at 2400/2400(Tx/Rx), V22bis, Normal,
None,
> Answer
> 19:29:16: TTY40: DSR came up
> 19:29:16: tty40: Modem: IDLE->READY
> 19:29:16: TTY40: EXEC creation
> 19:29:16: TTY40: set timer type 10, 30 seconds
> 19:29:20: TTY40: Autoselect(2) sample 2
> 19:29:20: TTY40: Autoselect(2) sample 201
> 19:29:20: TTY40: Autoselect(2) sample 20103
> 19:29:20: TTY40: set timer type 10, 30 seconds
> 19:29:22: TTY40: Autoselect(2) sample 201037E
> 19:29:22: TTY40: Autoselect(2) sample 1037EFF
> 19:29:22: TTY40: Autoselect(2) sample 37EFF7D
> 19:29:22: TTY40: Autoselect(2) sample 7EFF7D23
> 19:29:22: TTY40 Autoselect cmd: ppp negotiate
> 19:29:22: TTY40: EXEC creation
> 19:29:22: TTY40: create timer type 1, 600 seconds
> 19:29:22: As40 PPP: Consuming data in TTY40 receive queue
> 19:29:22: Async40: Setup PPP framing on TTY40
> 19:29:22: TTY40: destroy timer type 1 (OK)
> 19:29:22: TTY40: destroy timer type 0
> 19:29:22: As40 PPP: Async Protocol Mode started for 172.20.240.23
> 19:29:22: As40 AAA/ACCT: Using PPP accounting list ""
> 19:29:22: As40 PPP: Processed packet cached during autoselect
> 19:29:24: %LINK-3-UPDOWN: Interface Async40, changed state to up
> 19:29:24: As40 PPP: Treating connection as a dedicated line
> 19:29:24: As40 PPP: Phase is ESTABLISHING, Active Open
> 19:29:24: Modem 1/7 Mcom: PPP escape map: Tx map = FFFFFFFF, Rx map = 0
> 19:29:24: As40 LCP: O CONFREQ [Closed] id 163 len 25
> 19:29:24: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:24: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:24: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:24: As40 LCP: PFC (0x0702)
> 19:29:24: As40 LCP: ACFC (0x0802)
> 19:29:24: APPP40: Output packet, len = 29, header = FF 3 C0 21
> 19:29:24: APPP40: CRC error
> 19:29:24: APPP40: Input packet, len = 29, header = FF 3 C0 21
> 19:29:24: As40 PPP: I pkt type 0xC021, datagramsize 29
> 19:29:24: As40 PPP: I pkt type 0xC021, datagramsize 29
> 19:29:24: As40 LCP: I CONFACK [REQsent] id 163 len 25
> 19:29:24: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:24: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:24: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:24: As40 LCP: PFC (0x0702)
> 19:29:24: As40 LCP: ACFC (0x0802)
> 19:29:26: As40 LCP: TIMEout: State ACKrcvd
> 19:29:26: As40 LCP: O CONFREQ [ACKrcvd] id 164 len 25
> 19:29:26: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:26: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:26: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:26: As40 LCP: PFC (0x0702)
> 19:29:26: As40 LCP: ACFC (0x0802)
> 19:29:26: APPP40: Output packet, len = 29, header = FF 3 C0 21
> 19:29:26: APPP40: Input packet, len = 29, header = FF 3 C0 21
> 19:29:26: As40 PPP: I pkt type 0xC021, datagramsize 29
> 19:29:26: As40 PPP: I pkt type 0xC021, datagramsize 29
> 19:29:26: As40 LCP: I CONFACK [REQsent] id 164 len 25
> 19:29:26: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:26: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:26: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:26: As40 LCP: PFC (0x0702)
> 19:29:26: As40 LCP: ACFC (0x0802)
> 19:29:28: APPP40: Input packet, len = 27, header = FF 3 C0 21
> 19:29:28: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:28: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:28: As40 LCP: I CONFREQ [ACKrcvd] id 0 len 23
> 19:29:28: As40 LCP: ACCM 0x00000000 (0x020600000000)
> 19:29:28: As40 LCP: MagicNumber 0x00002DE2 (0x050600002DE2)
> 19:29:28: As40 LCP: PFC (0x0702)
> 19:29:28: As40 LCP: ACFC (0x0802)
> 19:29:28: As40 LCP: Callback 6 (0x0D0306)
> 19:29:28: Async40: Enabling PPP framing in UART's Microcode on line TTY40
> 19:29:28: Modem 1/7 Mcom: switching to PPP mode succeeded
> 19:29:28: As40 LCP: O CONFREJ [ACKrcvd] id 0 len 7
> 19:29:28: As40 LCP: Callback 6 (0x0D0306)
> 19:29:28: As40 LCP: TIMEout: State ACKrcvd
> 19:29:28: As40 LCP: O CONFREQ [ACKrcvd] id 165 len 25
> 19:29:28: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:28: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:28: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:28: As40 LCP: PFC (0x0702)
> 19:29:28: As40 LCP: ACFC (0x0802)
> 19:29:30: As40 LCP: TIMEout: State REQsent
> 19:29:30: As40 LCP: O CONFREQ [REQsent] id 166 len 25
> 19:29:30: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:30: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:30: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:30: As40 LCP: PFC (0x0702)
> 19:29:30: As40 LCP: ACFC (0x0802)
> 19:29:32: As40 LCP: TIMEout: State REQsent
> 19:29:32: As40 LCP: O CONFREQ [REQsent] id 167 len 25
> 19:29:32: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:32: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:32: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:32: As40 LCP: PFC (0x0702)
> 19:29:32: As40 LCP: ACFC (0x0802)
> 19:29:34: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:34: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:34: As40 LCP: I CONFREQ [REQsent] id 0 len 23
> 19:29:34: As40 LCP: ACCM 0x00000000 (0x020600000000)
> 19:29:34: As40 LCP: MagicNumber 0x00002DE2 (0x050600002DE2)
> 19:29:34: As40 LCP: PFC (0x0702)
> 19:29:34: As40 LCP: ACFC (0x0802)
> 19:29:34: As40 LCP: Callback 6 (0x0D0306)
> 19:29:34: As40 LCP: O CONFREJ [REQsent] id 0 len 7
> 19:29:34: As40 LCP: Callback 6 (0x0D0306)
> 19:29:34: As40 LCP: TIMEout: State REQsent
> 19:29:34: As40 LCP: O CONFREQ [REQsent] id 168 len 25
> 19:29:34: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:34: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:34: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:34: As40 LCP: PFC (0x0702)
> 19:29:34: As40 LCP: ACFC (0x0802)
> 19:29:36: As40 LCP: TIMEout: State REQsent
> 19:29:36: As40 LCP: O CONFREQ [REQsent] id 169 len 25
> 19:29:36: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:36: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:36: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:36: As40 LCP: PFC (0x0702)
> 19:29:36: As40 LCP: ACFC (0x0802)
> 19:29:38: As40 LCP: TIMEout: State REQsent
> 19:29:38: As40 LCP: O CONFREQ [REQsent] id 170 len 25
> 19:29:38: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:38: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:38: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:38: As40 LCP: PFC (0x0702)
> 19:29:38: As40 LCP: ACFC (0x0802)
> 19:29:40: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:40: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:40: As40 LCP: I CONFREQ [REQsent] id 0 len 23
> 19:29:40: As40 LCP: ACCM 0x00000000 (0x020600000000)
> 19:29:40: As40 LCP: MagicNumber 0x00002DE2 (0x050600002DE2)
> 19:29:40: As40 LCP: PFC (0x0702)
> 19:29:40: As40 LCP: ACFC (0x0802)
> 19:29:40: As40 LCP: Callback 6 (0x0D0306)
> 19:29:40: As40 LCP: O CONFREJ [REQsent] id 0 len 7
> 19:29:40: As40 LCP: Callback 6 (0x0D0306)
> 19:29:40: As40 LCP: TIMEout: State REQsent
> 19:29:40: As40 LCP: O CONFREQ [REQsent] id 171 len 25
> 19:29:40: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:40: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:40: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:40: As40 LCP: PFC (0x0702)
> 19:29:40: As40 LCP: ACFC (0x0802)
> 19:29:42: As40 LCP: TIMEout: State REQsent
> 19:29:42: As40 LCP: O CONFREQ [REQsent] id 172 len 25
> 19:29:42: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:42: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:42: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:42: As40 LCP: PFC (0x0702)
> 19:29:42: As40 LCP: ACFC (0x0802)
> 19:29:44: As40 LCP: TIMEout: State REQsent
> 19:29:44: As40 LCP: O CONFREQ [REQsent] id 173 len 25
> 19:29:44: As40 LCP: ACCM 0x000A0000 (0x0206000A0000)
> 19:29:44: As40 LCP: AuthProto CHAP (0x0305C22305)
> 19:29:44: As40 LCP: MagicNumber 0x54A1DD19 (0x050654A1DD19)
> 19:29:44: As40 LCP: PFC (0x0702)
> 19:29:44: As40 LCP: ACFC (0x0802)
> 19:29:46: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:46: As40 PPP: I pkt type 0xC021, datagramsize 27
> 19:29:46: As40 LCP: I CONFREQ [REQsent] id 0 len 23
> 19:29:46: As40 LCP: ACCM 0x00000000 (0x020600000000)
> 19:29:46: As40 LCP: MagicNumber 0x00002DE2 (0x050600002DE2)
> 19:29:46: As40 LCP: PFC (0x0702)
> 19:29:46: As40 LCP: ACFC (0x0802)
> 19:29:46: As40 LCP: Callback 6 (0x0D0306)
> 19:29:46: As40 LCP: O CONFREJ [REQsent] id 0 len 7
> 19:29:46: As40 LCP: Callback 6 (0x0D0306)
> 19:29:46: As40 LCP: TIMEout: State REQsent
> 19:29:46: TTY40: Async Int reset: Dropping DTR
> 19:29:46: As40 LCP: State is Listen
> 19:29:46: Modem 1/7 Mcom: in modem state 'Disconnecting'
> 19:29:46: Modem 1/7 Mcom: DISCONNECT, duration = 00:00:32, reason (0x9)
DTR
> Drop
> 19:29:47: TTY40: DSR was dropped
> 19:29:47: tty40: Modem: READY->HANGUP
> 19:29:47: Modem 1/7 Mcom: in modem state 'Idle'
> 19:29:48: TTY40: dropping DTR, hanging up
> 19:29:48: tty40: Modem: HANGUP->IDLE
> 19:29:48: %LINK-5-CHANGED: Interface Async40, changed state to reset
> 19:29:48: As40 LCP: State is Closed
> 19:29:48: As40 PPP: Phase is DOWN
> 19:29:48: As40 IPCP: Remove route to 172.20.240.23
> 19:29:49: TTY40: cleanup pending. Delaying DTR
> 19:29:50: TTY40: cleanup pending. Delaying DTR
> 19:29:51: TTY40: cleanup pending. Delaying DTR
> 19:29:51: Async40: Async protocol mode stopped for 0.0.0.0
> 19:29:51: Modem 1/7 Mcom: switching to character mode
> 19:29:51: Async40: Reset PPP framing on TTY40
> 19:29:51: TTY40: destroy timer type 0
> 19:29:51: TTY40: destroy timer type 1
> 19:29:51: TTY40: destroy timer type 3
> 19:29:51: TTY40: destroy timer type 4
> 19:29:51: TTY40: destroy timer type 2
> 19:29:51: Async40: allowing modem_process to continue hangup
> 19:29:52: TTY40: restoring DTR
> 19:29:53: TTY40: autoconfigure probe started
> 19:29:53: %LINK-3-UPDOWN: Interface Async40, changed state to down
> 19:29:53: As40 LCP: State is Closed
> 19:29:53: As40 PPP: Phase is DOWN



This archive was generated by hypermail 2b29 : Sun Aug 04 2002 - 04:11:59 EDT