Chat-script issue

netadmincsm · ‎06-15-2011

Hi all

I have Cisco 891 with integrated Async (V.92) interface. I do not use modemcap yet. I'm only running chat-script for AT configuration. I used this kind of setup on 831 with External USRobotics for 5 years on houndred sites.

Here's what I'm able to do with the 891

- Boot up the router

- Access AT command prompt using telnet [Loopback IP] on 2001 port

- Type an ATZ command

- Disconnect from AT command prompt

- Trigger the Dialing process

- Chat-script : ABORT ERROR "" "ATDT \T" TIMEOUT 60 CONNECT \c

- Async configuration :

ip address negotiated

encapsulation ppp

dialer in-band

dialer idle-timeout 60

dialer wait-for-carrier-time 10

dialer string XXXXXXX modem-script dialout

dialer watch-group 8

async dynamic address

async dynamic routing

async mode dedicated

no keepalive

ppp pap sent-username XXXXXXXX password XXXXXXX

- Line 1 configuration :

line 1

exec-timeout 0 0

modem InOut

stopbits 1

speed 115200

flowcontrol hardware

- I'm now connected to my ISP.

- Debug "ppp authe", "ppp nego", "chat line 1"

Jun 15 18:17:05: CHAT1: Attempting async line dialer script

Jun 15 18:17:05: CHAT1: Dialing using Modem script: dialout & System script: none

Jun 15 18:17:05: CHAT1: process started

Jun 15 18:17:05: CHAT1: Asserting DTR

Jun 15 18:17:05: CHAT1: Chat script dialout started

Jun 15 18:17:05: CHAT1: Sending string: ATDT \T<XXXXXXXXXX>

Jun 15 18:17:05: CHAT1: Expecting string: CONNECT

Jun 15 18:17:05: CHAT1: Input mismatch expecting: CONNECT :: ATDT XXXXXXXXXX\015

Jun 15 18:17:27: CHAT1: Input match for: CONNECT:: CONNECT

Jun 15 18:17:27: CHAT1: Completed match for expect: CONNECT

Jun 15 18:17:27: CHAT1: Sending string: \c

Jun 15 18:17:27: CHAT1: Chat script dialout finished, status = Success

Jun 15 18:17:29: %LINK-3-UPDOWN: Interface Async1, changed state to up

Jun 15 18:17:29: As1 PPP: Sending cstate UP notification

Jun 15 18:17:29: As1 PPP: Processing CstateUp message

Jun 15 18:17:29: PPP: Alloc Context [86445068]

Jun 15 18:17:29: ppp2 PPP: Phase is ESTABLISHING

Jun 15 18:17:29: As1 PPP: Using dialer call direction

Jun 15 18:17:29: As1 PPP: Treating connection as a callout

Jun 15 18:17:29: As1 PPP: Session handle[69000002] Session id[2]

Jun 15 18:17:29: As1 LCP: Event[OPEN] State[Initial to Starting]

Jun 15 18:17:29: As1 PPP: No remote authentication for call-out

Jun 15 18:17:29: As1 LCP: O CONFREQ [Starting] id 1 len 20

Jun 15 18:17:29: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:17:29: As1 LCP: MagicNumber 0x0109C3A9 (0x05060109C3A9)

Jun 15 18:17:29: As1 LCP: PFC (0x0702)

Jun 15 18:17:29: As1 LCP: ACFC (0x0802)

Jun 15 18:17:29: As1 LCP: Event[UP] State[Starting to REQsent]

Jun 15 18:17:29: As1 LCP: I CONFREQ [REQsent] id 116 len 42

Jun 15 18:17:29: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:17:29: As1 LCP: AuthProto PAP (0x0304C023)

Jun 15 18:17:29: As1 LCP: MagicNumber 0x628C6AB3 (0x0506628C6AB3)

Jun 15 18:17:29: As1 LCP: PFC (0x0702)

Jun 15 18:17:29: As1 LCP: ACFC (0x0802)

Jun 15 18:17:29: As1 LCP: MRRU 1524 (0x110405F4)

Jun 15 18:17:29: As1 LCP: EndpointDisc 1 QBCStackGrp (0x130E01514243537461636B477270)

Jun 15 18:17:29: As1 LCP: O CONFREJ [REQsent] id 116 len 8

Jun 15 18:17:29: As1 LCP: MRRU 1524 (0x110405F4)

Jun 15 18:17:29: As1 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]

Jun 15 18:17:29: As1 LCP: I CONFACK [REQsent] id 1 len 20

Jun 15 18:17:29: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:17:29: As1 LCP: MagicNumber 0x0109C3A9 (0x05060109C3A9)

Jun 15 18:17:29: As1 LCP: PFC (0x0702)

Jun 15 18:17:29: As1 LCP: ACFC (0x0802)

Jun 15 18:17:29: As1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

Jun 15 18:17:30: As1 LCP: I CONFREQ [ACKrcvd] id 117 len 38

Jun 15 18:17:30: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:17:30: As1 LCP: AuthProto PAP (0x0304C023)

Jun 15 18:17:30: As1 LCP: MagicNumber 0x628C6AB3 (0x0506628C6AB3)

Jun 15 18:17:30: As1 LCP: PFC (0x0702)

Jun 15 18:17:30: As1 LCP: ACFC (0x0802)

Jun 15 18:17:30: As1 LCP: EndpointDisc 1 QBCStackGrp (0x130E01514243537461636B477270)

Jun 15 18:17:30: As1 LCP: O CONFACK [ACKrcvd] id 117 len 38

Jun 15 18:17:30: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:17:30: As1 LCP: AuthProto PAP (0x0304C023)

Jun 15 18:17:30: As1 LCP: MagicNumber 0x628C6AB3 (0x0506628C6AB3)

Jun 15 18:17:30: As1 LCP: PFC (0x0702)

Jun 15 18:17:30: As1 LCP: ACFC (0x0802)

Jun 15 18:17:30: As1 LCP: EndpointDisc 1 QBCStackGrp (0x130E01514243537461636B477270)

Jun 15 18:17:30: As1 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

Jun 15 18:17:30: As1 PPP: Phase is AUTHENTICATING, by the peer

Jun 15 18:17:30: As1 PAP: Using hostname from interface PAP

Jun 15 18:17:30: As1 PAP: Using password from interface PAP

Jun 15 18:17:30: As1 PAP: O AUTH-REQ id 1 len 34 from "XXXXXXXX"

Jun 15 18:17:30: As1 LCP: State is Open

Jun 15 18:17:30: As1 PAP: I AUTH-ACK id 1 len 5

Jun 15 18:17:30: As1 PPP: Phase is FORWARDING, Attempting Forward

Jun 15 18:17:30: As1 PPP: Phase is ESTABLISHING, Finish LCP

Jun 15 18:17:30: As1 PPP: Phase is UP

Jun 15 18:17:30: As1 IPCP: Protocol configured, start CP. state[Initial]

Jun 15 18:17:30: As1 IPCP: Event[OPEN] State[Initial to Starting]

Jun 15 18:17:30: As1 IPCP: O CONFREQ [Starting] id 1 len 10

Jun 15 18:17:30: As1 IPCP: Address 0.0.0.0 (0x030600000000)

Jun 15 18:17:30: As1 IPCP: Event[UP] State[Starting to REQsent]

Jun 15 18:17:30: As1 IPCP: I CONFREQ [REQsent] id 239 len 16

Jun 15 18:17:30: As1 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC99F2)

Jun 15 18:17:30: As1 IPCP: O CONFREJ [REQsent] id 239 len 10

Jun 15 18:17:30: As1 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

Jun 15 18:17:30: As1 IPCP: Event[Receive ConfReq-] State[REQsent to REQsent]

Jun 15 18:17:30: As1 IPCP: I CONFREQ [REQsent] id 240 len 16

Jun 15 18:17:30: As1 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC99F2)

Jun 15 18:17:30: As1 IPCP: O CONFREJ [REQsent] id 240 len 10

Jun 15 18:17:30: As1 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

Jun 15 18:17:30: As1 IPCP: Event[Receive ConfReq-] State[REQsent to REQsent]

Jun 15 18:17:30: As1 IPCP: I CONFNAK [REQsent] id 1 len 10

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC9995)

Jun 15 18:17:30: As1 IPCP: O CONFREQ [REQsent] id 2 len 10

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC9995)

Jun 15 18:17:30: As1 IPCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

Jun 15 18:17:30: As1 IPCP: I CONFREQ [REQsent] id 241 len 10

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC99F2)

Jun 15 18:17:30: As1 IPCP: O CONFACK [REQsent] id 241 len 10

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC99F2)

Jun 15 18:17:30: As1 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]

Jun 15 18:17:30: As1 IPCP: I CONFACK [ACKsent] id 2 len 10

Jun 15 18:17:30: As1 IPCP: Address 111.111.111.111 (0x0306CEAC9995)

Jun 15 18:17:30: As1 IPCP: Event[Receive ConfAck] State[ACKsent to Open]

Jun 15 18:17:30: As1 IPCP: State is Open

Jun 15 18:17:30: As1 IPCP: Install negotiated IP interface address 111.111.111.111

Jun 15 18:17:30: As1 Added to neighbor route AVL tree: topoid 0, address 111.111.111.111

Jun 15 18:17:30: As1 IPCP: Install route to 111.111.111.111

Here's what I'm not able to do with the 891

If I try to add the ATZ I did manually into the chat-script I have the following :

- Boot up the router

- Trigger the Dialing process

- Chat-script : ABORT ERROR "" "ATZ" OK "ATDT \T" TIMEOUT 60 CONNECT \c

- Async configuration :

ip address negotiated

encapsulation ppp

dialer in-band

dialer idle-timeout 60

dialer wait-for-carrier-time 10

dialer string XXXXXXX modem-script dialout

dialer watch-group 8

async dynamic address

async dynamic routing

async mode dedicated

no keepalive

ppp pap sent-username XXXXXXXX password XXXXXXX

- Line 1 configuration :

line 1

exec-timeout 0 0

modem InOut

stopbits 1

speed 115200

flowcontrol hardware

- I'm not able to connect to my ISP.

- Debug "ppp authe", "ppp nego", "chat line 1"

Jun 15 18:56:04: CHAT1: Attempting async line dialer script

Jun 15 18:56:04: CHAT1: Dialing using Modem script: dialout & System script: none

Jun 15 18:56:04: CHAT1: process started

Jun 15 18:56:04: CHAT1: Asserting DTR

Jun 15 18:56:04: CHAT1: Chat script dialout started

Jun 15 18:56:04: CHAT1: Sending string: ATZ

Jun 15 18:56:04: CHAT1: Expecting string: OK

Jun 15 18:56:04: CHAT1: Input mismatch expecting: OK :: ATZ\015\015\012

Jun 15 18:56:04: CHAT1: Input match for: OK:: OK

Jun 15 18:56:04: CHAT1: Completed match for expect: OK

Jun 15 18:56:08: CHAT1: Sending string: ATDT \T<XXXXXXXXXX>

Jun 15 18:56:08: CHAT1: Expecting string: CONNECT

Jun 15 18:56:08: CHAT1: Input mismatch expecting: CONNECT :: AT+MR=1\015\015\012OK\015\012AT+DR=1\015\015\012OK\015\012AT\V4\015\015\012OK\015\012ATS0=1\015\015\012OK\015\012AT:U70,A700\015\015\012OK\015\012AT&D2\015\015\012OK\015\012ATE1\015\015\012OK\015\012ATDT XXXXXXXXXX\015\015\012+M

Jun 15 18:56:30: CHAT1: Input match for: CONNECT:: C

Jun 15 18:56:30: CHAT1: Input mismatch expecting: CONNECT :: R:V90\015\012\015\012+MRR:24000,50666\015\012\015\012+DR:V44 \015\012\015\012

Jun 15 18:56:30: CHAT1: Input match for: CONNECT:: CONNECT

Jun 15 18:56:30: CHAT1: Completed match for expect: CONNECT

Jun 15 18:56:30: CHAT1: Sending string: \c

Jun 15 18:56:30: CHAT1: Chat script dialout finished, status = Success

Jun 15 18:56:32: %LINK-3-UPDOWN: Interface Async1, changed state to up

Jun 15 18:56:32: As1 PPP: Sending cstate UP notification

Jun 15 18:56:32: As1 PPP: Processing CstateUp message

Jun 15 18:56:32: PPP: Alloc Context [860A26E8]

Jun 15 18:56:32: ppp2 PPP: Phase is ESTABLISHING

Jun 15 18:56:32: As1 PPP: Using dialer call direction

Jun 15 18:56:32: As1 PPP: Treating connection as a callout

Jun 15 18:56:32: As1 PPP: Session handle[D8000002] Session id[2]

Jun 15 18:56:32: As1 LCP: Event[OPEN] State[Initial to Starting]

Jun 15 18:56:32: As1 PPP: No remote authentication for call-out

Jun 15 18:56:32: As1 LCP: O CONFREQ [Starting] id 1 len 20

Jun 15 18:56:32: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:32: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:32: As1 LCP: PFC (0x0702)

Jun 15 18:56:32: As1 LCP: ACFC (0x0802)

Jun 15 18:56:32: As1 LCP: Event[UP] State[Starting to REQsent]

Jun 15 18:56:34: As1 LCP: O CONFREQ [REQsent] id 2 len 20

Jun 15 18:56:34: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:34: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:34: As1 LCP: PFC (0x0702)

Jun 15 18:56:34: As1 LCP: ACFC (0x0802)

Jun 15 18:56:34: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:36: As1 LCP: O CONFREQ [REQsent] id 3 len 20

Jun 15 18:56:36: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:36: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:36: As1 LCP: PFC (0x0702)

Jun 15 18:56:36: As1 LCP: ACFC (0x0802)

Jun 15 18:56:36: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:38: As1 LCP: O CONFREQ [REQsent] id 4 len 20

Jun 15 18:56:38: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:38: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:38: As1 LCP: PFC (0x0702)

Jun 15 18:56:38: As1 LCP: ACFC (0x0802)

Jun 15 18:56:38: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:40: As1 LCP: O CONFREQ [REQsent] id 5 len 20

Jun 15 18:56:40: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:40: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:40: As1 LCP: PFC (0x0702)

Jun 15 18:56:40: As1 LCP: ACFC (0x0802)

Jun 15 18:56:40: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:42: As1 LCP: O CONFREQ [REQsent] id 6 len 20

Jun 15 18:56:42: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:42: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:42: As1 LCP: PFC (0x0702)

Jun 15 18:56:42: As1 LCP: ACFC (0x0802)

Jun 15 18:56:42: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:42: As1 LCP: I CONFREQ [REQsent] id 6 len 20

Jun 15 18:56:42: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:42: As1 LCP: MagicNumber 0x0103CB4C (0x05060103CB4C)

Jun 15 18:56:42: As1 LCP: PFC (0x0702)

Jun 15 18:56:42: As1 LCP: ACFC (0x0802)

Jun 15 18:56:42: As1 LCP: Loopback seen, Magic number not Acked

Jun 15 18:56:42: As1 LCP: O CONFNAK [REQsent] id 6 len 10

Jun 15 18:56:42: As1 LCP: MagicNumber 0x0103F2A3 (0x05060103F2A3)

Jun 15 18:56:42: As1 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]

Jun 15 18:56:42: As1 LCP: I CONFNAK [REQsent] id 6 len 10

Jun 15 18:56:42: As1 LCP: MagicNumber 0x0103F2A3 (0x05060103F2A3)

Jun 15 18:56:42: As1 PPP: Line appears to be looped back

Jun 15 18:56:45: As1 LCP: O CONFREQ [REQsent] id 7 len 20

Jun 15 18:56:45: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jun 15 18:56:45: As1 LCP: MagicNumber 0x0103F2A8 (0x05060103F2A8)

Jun 15 18:56:45: As1 LCP: PFC (0x0702)

Jun 15 18:56:45: As1 LCP: ACFC (0x0802)

Jun 15 18:56:45: As1 LCP: Event[Timeout+] State[REQsent to REQsent]

Jun 15 18:56:45: %LINK-5-CHANGED: Interface Async1, changed state to reset

Jun 15 18:56:45: As1 PPP: Sending cstate DOWN notification

Jun 15 18:56:45: As1 PPP: Processing CstateDown message

Jun 15 18:56:45: As1 PPP DISC: Lower Layer disconnected

Jun 15 18:56:45: As1 PPP: Sending Acct Event[Down] id[E]

Jun 15 18:56:45: PPP: NET STOP send to AAA.

Jun 15 18:56:45: As1 LCP: O TERMREQ [REQsent] id 8 len 4

Jun 15 18:56:45: As1 LCP: Event[CLOSE] State[REQsent to Closing]

Jun 15 18:56:45: As1 PPP: Phase is TERMINATING

Jun 15 18:56:45: As1 LCP: Event[DOWN] State[Closing to Initial]

Jun 15 18:56:45: As1 PPP: Phase is DOWN

NOTE : If I try to use the Factory default option from a modemcap instead of ATZ with CHAT-SCRIPT I have the same issue

Why am I able to connect only when I use the ATZ manually ?

I'm confused :|

Thanks for your help

paolo bevilacqua · ‎06-15-2011

Already asked in another thread, please avoid posting duplicates.

netadmincsm · ‎06-16-2011

I know, I tried to delete the old post but it doesn't work.

We advanced in the issue. We now have trouble with chat-script.

The post is different.

Sorry for the inconvenient.

paolo bevilacqua · ‎06-17-2011

It's strange, somehow the chat script seems acting completely wrong.