Re: Callback with Mica didn't work

dcristoni · ‎04-16-2003

My router is 3640 with module 4 bri s/t and six mica modem.

The authentication (user test password cisco) is ok but the router didn't initiate the callback.

Why?

Many thanks.

service timestamps debug datetime msec

service timestamps log datetime msec

no service password-encryption

!

username test callback-dialstring "" password cisco

memory-size iomem 40

modem call-record terse

modem country mica italy

ip subnet-zero

!

isdn switch-type basic-net3

chat-script offhook "" "ATH1" OK

chat-script callback ABORT ERROR ABORT BUSY "" "ATZ" OK "ATDT \T" TIMEOUT60 CONNECT \c

modemcap entry aster:MSC=&F&D2S0=0S34=18000S40=10S10=50debugthismodemS71=4

!

interface Loopback0

ip address 192.168.19.254 255.255.255.0

!

interface BRI1/0

no ip address

encapsulation ppp

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/1

no ip address

encapsulation ppp

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/2

no ip address

encapsulation ppp

shutdown

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/3

no ip address

encapsulation ppp

shutdown

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface Ethernet3/0

ip address 192.168.10.10 255.255.255.0

half-duplex

no cdp enable

!

interface Group-Async1

ip unnumbered Loopback0

encapsulation ppp

ip tcp header-compression

no ip mroute-cache

async mode dedicated

peer default ip address pool set

ppp callback permit

ppp authentication pap chap ms-chap

group-range 1 6

!

interface Dialer1

ip unnumbered Loopback0

encapsulation ppp

no ip mroute-cache

dialer-group 1

peer default ip address pool set

no fair-queue

no cdp enable

ppp authentication pap chap ms-chap

!

ip local pool set 192.168.19.12 192.168.19.241

ip classless

ip route 0.0.0.0 0.0.0.0 192.168.10.1

no ip http server

!

dialer-list 1 protocol ip permit

no cdp run

!

line con 0

line 1 6

no flush-at-activation

script reset default

script modem-off-hook offhook

script callback callback

modem Dialin

modem autoconfigure type aster

transport input all

autoselect during-login

autoselect ppp

callback forced-wait 10

line aux 0

line vty 0

password 3640

login

length 25

line vty 1 4

password 3640

login

makchitale · ‎04-16-2003

Need to add the "ppp callback accept" under the int group-asyn 1.

http://www.cisco.com/warp/public/793/access_dial/async_ppp.html

http://www.cisco.com/univercd/cc/td/doc/product/software/ios120/12cgcr/dial_c/dccalldd.htm

Thanks, Mak.

tepatel · ‎04-16-2003

Since "ppp callback permit" is there, no need to have "ppp callback accept" under the group-async interface. "permit" will allow user to enter callback number to be called back by router or cancel the callback to have a ppp connectioin directly. So that way choice is given to user for callback with "permit"

Anyway, try to match the config as pointed in those two urls. if that atill dosen't work, we need to see the debug for following and post it here.

debug ppp nego

debug aaa authorization

debug ppp cbcp

debug callback

debug isdn q931

debug dialer

debug modem csm

debug chat

dcristoni · ‎04-16-2003

This is an incomplete debug,the modem don't go offhook.

First Part

*Mar 13 01:46:46.500: ISDN BR1/1: RX <- SETUP pd = 8 callref = 0x06

*Mar 13 01:46:46.504: Sending Complete

*Mar 13 01:46:46.504: Bearer Capability i = 0x9090A3

*Mar 13 01:46:46.504: Channel ID i = 0x8A

*Mar 13 01:46:46.504: Progress Ind i = 0x8183 - Origination address is non-ISDN

*Mar 13 01:46:46.504: Calling Party Number i = 0x00, 0xA3, Plan:Unknown, Type:Unknown

*Mar 13 01:46:46.504: Called Party Number i = 0xA1, '516344501', Plan:ISDN, Type:National

*Mar 13 01:46:46.508: ISDN BR1/1: Event: Received a VOICE call from on B2 at 64 Kb/s

*Mar 13 01:46:46.512: ISDN BR1/1: Event: Accepting the call id 0x7F

*Mar 13 01:46:46.512: CSM: MODEM_REPORT from 1/1:1, call_id=0x7F, event=0x1, cause=0x0, dchan_idb=0x611DE610

*Mar 13 01:46:46.512: CSM: Next free modem = 0/0; statbits = 80010020

*Mar 13 01:46:46.512: Modem 0/0 CSM: modem is allocated, modems free=4

*Mar 13 01:46:46.512: Modem 0/0 CSM: Incoming call from Unknown to 516344501, id 0x7F

*Mar 13 01:46:46.512: Modem 0/0 CSM: (CSM_PROC_IDLE)<--ISDN_CALL

*Mar 13 01:46:46.552: ISDN BR1/1: TX -> CALL_PROC pd = 8 callref = 0x86

*Mar 13 01:46:46.552: Channel ID i = 0x8A

*Mar 13 01:46:46.576: ISDN BR1/1: TX -> ALERTING pd = 8 callref = 0x86

*Mar 13 01:46:46.600: ISDN BR1/1: TX -> CONNECT pd = 8 callref = 0x86

*Mar 13 01:46:46.724: ISDN BR1/1: RX <- CONNECT_ACK pd = 8 callref = 0x06

*Mar 13 01:46:46.728: CSM: MODEM_REPORT from 1/1:1, call_id=0x7F, event=0x4, cause=0x0, dchan_idb=0x611DE610

*Mar 13 01:46:46.728: Modem 0/0 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0x7F

*Mar 13 01:46:46.728: Modem 0/0 CSM: (CSM_PROC_MODEM_RESERVED)<--ISDN_CONNECTED

*Mar 13 01:46:46.728: Modem 0/0 Mica: configured for Answer mode, with Null signaling, 0x0 tone detection.

*Mar 13 01:46:46.820: Modem 0/0 Mica: in modem state CALL_SETUP

*Mar 13 01:46:46.848: Modem 0/0 Mica: in modem state CONNECT

*Mar 13 01:46:51.336: Modem 0/0 Mica: in modem state LINK

*Mar 13 01:46:52.728: %ISDN-6-CONNECT: Interface BRI1/1:2 is now connected to unknown

*Mar 13 01:47:02.932: Modem 0/0 Mica: in modem state TRAINUP

*Mar 13 01:47:06.824: Modem 0/0 Mica: in modem state EC_NEGOTIATING

*Mar 13 01:47:07.084: Modem 0/0 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--MODEM_CONNECTED

*Mar 13 01:47:07.084: Modem 0/0 Mica: in modem state STEADY

*Mar 13 01:47:07.096: Modem 0/0 Mica: CONNECT at 50666/26400 (Tx/Rx), V90, LAPM, V42bis

*Mar 13 01:47:07.816: TTY1: DSR came up

*Mar 13 01:47:07.816: TTY1: no timer type 1 to destroy

*Mar 13 01:47:07.816: TTY1: no timer type 0 to destroy

*Mar 13 01:47:07.816: TTY1: no timer type 2 to destroy

*Mar 13 01:47:07.816: tty1: Modem: IDLE->(unknown)

*Mar 13 01:47:08.364: Modem 0/0 Mica: in modem state SS_SHIFTINGSPEED

*Mar 13 01:47:09.816: %LINK-3-UPDOWN: Interface Async1, changed state to up

*Mar 13 01:47:09.816: As1 PPP: Using modem call direction

*Mar 13 01:47:09.816: As1 PPP: Treating connection as a callin

*Mar 13 01:47:09.816: As1 PPP: Phase is ESTABLISHING, Passive Open [0 sess, 1 load]

*Mar 13 01:47:09.816: As1 LCP: State is Listen

*Mar 13 01:47:09.904: Modem 0/0 CSM: (CSM_PROC_CONNECTED)<--MODEM_CONNECTED

*Mar 13 01:47:09.904: Modem 0/0 Mica: in modem state STEADY

*Mar 13 01:47:09.912: Modem 0/0 Mica: SpeedShifted to 49333/26400 (Tx/Rx)

*Mar 13 01:47:10.256: As1 LCP: I CONFREQ [Listen] id 2 len 23

*Mar 13 01:47:10.256: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

*Mar 13 01:47:10.256: As1 LCP: MagicNumber 0x00069FAF (0x050600069FAF)

*Mar 13 01:47:10.256: As1 LCP: PFC (0x0702)

*Mar 13 01:47:10.256: As1 LCP: ACFC (0x0802)

*Mar 13 01:47:10.256: As1 LCP: Callback 6 (0x0D0306)

*Mar 13 01:47:10.256: Modem 0/0 Mica: PPP escape_map: Tx map = FFFFFFFF, Rx map = 0

*Mar 13 01:47:10.260: As1 LCP: O CONFREQ [Listen] id 22 len 24

*Mar 13 01:47:10.260: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

*Mar 13 01:47:10.260: As1 LCP: AuthProto PAP (0x0304C023)

*Mar 13 01:47:10.260: As1 LCP: MagicNumber 0x9EB1A71A (0x05069EB1A71A)

*Mar 13 01:47:10.260: As1 LCP: PFC (0x0702)

*Mar 13 01:47:10.260: As1 LCP: ACFC (0x0802)

*Mar 13 01:47:10.260: As1 LCP: O CONFACK [Listen] id 2 len 23

*Mar 13 01:47:10.260: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

*Mar 13 01:47:10.260: As1 LCP: MagicNumber 0x00069FAF (0x050600069FAF)

*Mar 13 01:47:10.260: As1 LCP: PFC (0x0702)

*Mar 13 01:47:10.260: As1 LCP: ACFC (0x0802)

*Mar 13 01:47:10.260: As1 LCP: Callback 6 (0x0D0306)

*Mar 13 01:47:10.396: As1 LCP: I CONFACK [ACKsent] id 22 len 24

*Mar 13 01:47:10.400: As1 LCP: ACCM 0x000A0000 (0x0206000A0000)

*Mar 13 01:47:10.400: As1 LCP: AuthProto PAP (0x0304C023)

*Mar 13 01:47:10.400: As1 LCP: MagicNumber 0x9EB1A71A (0x05069EB1A71A)

*Mar 13 01:47:10.400: As1 LCP: PFC (0x0702)

*Mar 13 01:47:10.400: As1 LCP: ACFC (0x0802)

*Mar 13 01:47:10.400: As1 LCP: State is Open

*Mar 13 01:47:10.400: Modem 0/0 Mica: PPP escape_map: Tx map = A0000, Rx map = 0

*Mar 13 01:47:10.400: As1 PPP: Phase is AUTHENTICATING, by this end [0 sess, 1 load]

*Mar 13 01:47:10.420: As1 PAP: I AUTH-REQ id 1 len 14 from "nps"

*Mar 13 01:47:10.420: As1 PAP: Authenticating peer nps

*Mar 13 01:47:10.420: As1 PAP: O AUTH-ACK id 1 len 5

*Mar 13 01:47:10.420: As1 MCB: User nps Callback Number - Client ANY

*Mar 13 01:47:10.420: Async1 PPP: O MCB Request(1) id 4 len 11

*Mar 13 01:47:10.420: Async1 MCB: O 1 4 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:10.424: As1 MCB: O Request Id 4 Callback Types Client-Num and None delay 0

*Mar 13 01:47:10.424: As1 PPP: Phase is CBCP [0 sess, 1 load]

*Mar 13 01:47:11.420: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async1, changed state to up

*Mar 13 01:47:12.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:12.420: Async1 PPP: O MCB Request(1) id 5 len 11

*Mar 13 01:47:12.420: Async1 MCB: O 1 5 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:12.420: As1 MCB: O Request Id 5 Callback Types Client-Num and None delay 0

*Mar 13 01:47:12.504: Modem 0/0 Mica: in modem state SS_SHIFTINGSPEED

*Mar 13 01:47:14.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:14.420: Async1 PPP: O MCB Request(1) id 6 len 11

*Mar 13 01:47:14.420: Async1 MCB: O 1 6 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:14.420: As1 MCB: O Request Id 6 Callback Types Client-Num and None delay 0

*Mar 13 01:47:16.016: Modem 0/0 Mica: in modem state SS_RETRAINING

*Mar 13 01:47:16.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:16.420: Async1 PPP: O MCB Request(1) id 7 len 11

*Mar 13 01:47:16.420: Async1 MCB: O 1 7 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:16.420: As1 MCB: O Request Id 7 Callback Types Client-Num and None delay 0

*Mar 13 01:47:18.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:18.420: Async1 PPP: O MCB Request(1) id 8 len 11

*Mar 13 01:47:18.420: Async1 MCB: O 1 8 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:18.420: As1 MCB: O Request Id 8 Callback Types Client-Num and None delay 0

*Mar 13 01:47:20.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:20.420: Async1 PPP: O MCB Request(1) id 9 len 11

*Mar 13 01:47:20.420: Async1 MCB: O 1 9 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:20.420: As1 MCB: O Request Id 9 Callback Types Client-Num and None delay 0

*Mar 13 01:47:22.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:22.420: Async1 PPP: O MCB Request(1) id 10 len 11

*Mar 13 01:47:22.420: Async1 MCB: O 1 A 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:22.420: As1 MCB: O Request Id 10 Callback Types Client-Num and None delay 0

*Mar 13 01:47:24.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:24.420: Async1 PPP: O MCB Request(1) id 11 len 11

*Mar 13 01:47:24.420: Async1 MCB: O 1 B 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:24.420: As1 MCB: O Request Id 11 Callback Types Client-Num and None delay 0

*Mar 13 01:47:26.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:26.420: Async1 PPP: O MCB Request(1) id 12 len 11

*Mar 13 01:47:26.420: Async1 MCB: O 1 C 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:26.420: As1 MCB: O Request Id 12 Callback Types Client-Num and None delay 0

*Mar 13 01:47:28.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:28.420: Async1 PPP: O MCB Request(1) id 13 len 11

*Mar 13 01:47:28.420: Async1 MCB: O 1 D 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:28.420: As1 MCB: O Request Id 13 Callback Types Client-Num and None delay 0

*

dcristoni · ‎04-16-2003

Second Part

Mar 13 01:47:28.676: Modem 0/0 CSM: (CSM_PROC_CONNECTED)<--MODEM_CONNECTED

*Mar 13 01:47:28.680: Modem 0/0 Mica: in modem state STEADY

*Mar 13 01:47:28.688: Modem 0/0 Mica: Retrained to 50666/26400 (Tx/Rx)

*Mar 13 01:47:29.072: Modem 0/0 Mica: in modem state SS_SHIFTINGSPEED

*Mar 13 01:47:30.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:30.420: Async1 PPP: O MCB Request(1) id 14 len 11

*Mar 13 01:47:30.420: Async1 MCB: O 1 E 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:30.420: As1 MCB: O Request Id 14 Callback Types Client-Num and None delay 0

*Mar 13 01:47:30.612: Modem 0/0 CSM: (CSM_PROC_CONNECTED)<--MODEM_CONNECTED

*Mar 13 01:47:30.612: Modem 0/0 Mica: in modem state STEADY

*Mar 13 01:47:30.620: Modem 0/0 Mica: SpeedShifted to 49333/26400 (Tx/Rx)

*Mar 13 01:47:32.420: As1 MCB: Timeout in state WAIT_RESPONSE

*Mar 13 01:47:32.420: Async1 PPP: O MCB Request(1) id 15 len 11

*Mar 13 01:47:32.420: Async1 MCB: O 1 F 0 B 1 2 2 5 0 1 0

*Mar 13 01:47:32.420: As1 MCB: O Request Id 15 Callback Types Client-Num and None delay 0

*Mar 13 01:47:32.464: Async1 PPP: I MCB Response(2) id 4 len 19

*Mar 13 01:47:32.464: Async1 MCB: I 2 4 0 13 2 F F 1 30 35 31 36 33 39 38 31 35 30 0

*Mar 13 01:47:32.464: As1 MCB: Received response

*Mar 13 01:47:32.464: As1 MCB: Resp ignored. ID Expected 15, got id 4

*Mar 13 01:47:32.540: Async1 PPP: I MCB Response(2) id 15 len 19

*Mar 13 01:47:32.540: Async1 MCB: I 2 F 0 13 2 F F 1 30 35 31 36 33 39 38 31 35 30 0

*Mar 13 01:47:32.540: As1 MCB: Received response

*Mar 13 01:47:32.540: As1 MCB: Response CBK-Client-Num 2 15 15, addr 1-0516398150

*Mar 13 01:47:32.540: Async1 PPP: O MCB Ack(3) id 15 len 19

*Mar 13 01:47:32.540: Async1 MCB: O 3 F 0 13 2 F F 1 30 35 31 36 33 39 38 31 35 30 0

*Mar 13 01:47:32.544: As1 MCB: O Ack Id 15 Callback Type Client-Num delay 15

*Mar 13 01:47:32.544: As1 MCB: Negotiated MCB with peer

*Mar 13 01:47:32.664: As1 LCP: I TERMREQ [Open] id 3 len 4

*Mar 13 01:47:32.664: As1 LCP: O TERMACK [Open] id 3 len 4

*Mar 13 01:47:32.664: As1 MCB: Peer terminating the link

*Mar 13 01:47:32.664: As1 MCB: Link terminated by peer, Callback Needed

*Mar 13 01:47:32.664: As1 MCB: Initiate Callback for nps at 0516398150 using Async

*Mar 13 01:47:32.664: TTY1 Callback user nps dialstring 0516398150 from PPP negotiation

*Mar 13 01:47:32.668: As1 MCB: Async-callback in progress

*Mar 13 01:47:32.668: As1 PPP: Phase is TERMINATING [0 sess, 1 load]

*Mar 13 01:47:32.668: TTY1 Callback PPP process creation

*Mar 13 01:47:32.668: TTY1 callback unavailable on line for PPP Callback

*Mar 13 01:47:32.668: TTY1: Line reset by "Callback PPP"

*Mar 13 01:47:32.668: CHAT1: Attempting line reset script

*Mar 13 01:47:32.668: CHAT1: No matching chat script found for default

*Mar 13 01:47:32.668: TTY1: Modem: (unknown)->HANGUP

*Mar 13 01:47:32.668: TTY1: no timer type 0 to destroy

*Mar 13 01:47:32.668: TTY1: no timer type 1 to destroy

*Mar 13 01:47:32.668: TTY1: no timer type 3 to destroy

*Mar 13 01:47:32.668: TTY1: no timer type 4 to destroy

*Mar 13 01:47:32.668: TTY1: no timer type 2 to destroy

*Mar 13 01:47:32.788: Modem 0/0 Mica: in modem state TERMINATING

*Mar 13 01:47:32.804: Modem 0/0 CSM: (CSM_PROC_CONNECTED)<--MODEM_DISCONNECTED

*Mar 13 01:47:32.804: Modem 0/0 Mica: in modem state IDLE

*Mar 13 01:47:32.804: Modem 0/0 CSM: (CSM_PROC_CONNECTED)<--QUEUED_DISCONNECT

*Mar 13 01:47:32.836: Modem 0/0 CSM: CSM_MODEM_DEALLOCATE: modem is deallocated

*Mar 13 01:47:32.836: %ISDN-6-DISCONNECT: Interface BRI1/1:2 disconnected from unknown , call lasted 46 seconds

*Mar 13 01:47:32.840: ISDN BR1/1: TX -> DISCONNECT pd = 8 callref = 0x86

*Mar 13 01:47:32.840: Cause i = 0x8090 - Normal call clearing

*Mar 13 01:47:32.844: Modem 0/0 Mica: DISCONNECT after 00:00:46, due to reason (0x8220) EC rcvd DISC frame.

*Mar 13 01:47:32.844: %CALLRECORD-3-MICA_TERSE_CALL_REC: DS0 slot/contr/chan=1/1/1, slot/port=0/0, call_id=7F, userid=dana, ip=0.0.0

.0, calling=3484771741, called=516344501, std=V90, prot=LAPM, comp = V42bis init-rx/tx b-rate=26400/50666, finl-rx/tx b-rate=26400/4

9333, rbs=0, d-pad=(invalid#256), retr=3, rx/tx chars=187/275, bad=27, rx/tx ec=13/17, bad=351, time=46, finl-state=STEADY, disc(mod

em)=8220 Rx (line to host) data flushing - OK/EC condition - locally detected/received DISC frame -- normal LAPM termination

*Mar 13 01:47:32.888: TTY1: dropping DTR, hanging up

*Mar 13 01:47:32.888: Modem 0/0 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

*Mar 13 01:47:32.888: TTY1: Async Int reset: Dropping DTR

*Mar 13 01:47:32.888: Modem 0/0 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

*Mar 13 01:47:32.888: tty1: Modem: HANGUP->IDLE

*Mar 13 01:47:32.888: TTY1: cleanup pending. Delaying DTR

*Mar 13 01:47:32.960: ISDN BR1/1: RX <- RELEASE pd = 8 callref = 0x06

*Mar 13 01:47:32.964: CSM: MODEM_REPORT from 1/1:1, call_id=0x7F, event=0x0, cause=0x0, dchan_idb=0x611DE610

*Mar 13 01:47:32.964: CSM: MODEM_REPORT rcvd DEV_IDLE for call_id 0x7F, modem not found due to wrong b channel number or b channel i

s deallocated

*Mar 13 01:47:32.968: ISDN BR1/1: TX -> RELEASE_COMP pd = 8 callref = 0x86

*Mar 13 01:47:33.664: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async1, changed state to down

*Mar 13 01:47:33.916: TTY1: cleanup pending. Delaying DTR

*Mar 13 01:47:34.668: As1 LCP: TIMEout: State TERMsent

*Mar 13 01:47:34.668: As1 LCP: State is Closed

*Mar 13 01:47:34.668: As1 PPP: Phase is DOWN [0 sess, 1 load]

*Mar 13 01:47:34.668: As1 PPP: Phase is ESTABLISHING, Passive Open [0 sess, 1 load]

*Mar 13 01:47:34.668: As1 LCP: State is Listen

*Mar 13 01:47:34.888: %LINK-5-CHANGED: Interface Async1, changed state to reset

*Mar 13 01:47:34.888: As1 LCP: State is Closed

*Mar 13 01:47:34.888: As1 PPP: Phase is DOWN [0 sess, 1 load]

*Mar 13 01:47:34.928: TTY1: cleanup pending. Delaying DTR

*Mar 13 01:47:35.936: TTY1: cleanup pending. Delaying DTR

*Mar 13 01:47:36.940: TTY1: cleanup pending. Delaying DTR

*Mar 13 01:47:37.888: TTY1: no timer type 0 to destroy

*Mar 13 01:47:37.888: TTY1: no timer type 1 to destroy

*Mar 13 01:47:37.888: TTY1: no timer type 3 to destroy

*Mar 13 01:47:37.888: TTY1: no timer type 4 to destroy

*Mar 13 01:47:37.888: TTY1: no timer type 2 to destroy

*Mar 13 01:47:37.888: Async1: allowing modem_process to continue hangup

*Mar 13 01:47:37.888: CHAT1: Attempting line reset script

*Mar 13 01:47:37.888: CHAT1: No matching chat script found for default

*Mar 13 01:47:37.944: TTY1: restoring DTR

*Mar 13 01:47:37.944: Modem 0/0 CSM: received ASYNC_DTR_UP for line 1

*Mar 13 01:47:37.952: TTY1: autoconfigure probe started

*Mar 13 01:47:37.956: TTY1: Modem command: --AT&F&D2S0=0S34=18000S40=10S10=50debugthismodemS71=4--

*Mar 13 01:47:38.516: TTY1: Modem configuration succeeded

*Mar 13 01:47:38.516: TTY1: Detected modem speed 115200

*Mar 13 01:47:38.516: TTY1: Done with modem configuration

*Mar 13 01:47:39.888: %LINK-3-UPDOWN: Interface Async1, changed state to down

*Mar 13 01:47:39.888: As1 LCP: State is Closed

Thanks

tepatel · ‎04-16-2003

Here is the debug line which indicate the issue

"*Mar 13 01:47:32.668: TTY1 callback unavailable on line for PPP Callback "

After looking on the line config you have "modem Dialin" configured and for callback router has to dialout. So to fix that issue use command "modem inout" under the line config instead of "modem dialin"

dcristoni · ‎04-17-2003

I added on the line config the command "modem inout" instead "modem dialin" but the error TTY1 callback unavailable on line for PPP Callback " remains.

Do you have any ideas?

Thanks

tepatel · ‎04-19-2003

Just make sure that the username used for dialin (and callback) is configured like the use "test" is configured. From the debug the username used is "nps" and i can't see that is configured in the router like user "test"

Anyway, Now need to know how far the user go when he dialin. Does he get the window to specify the callback number to be called back at?

What exactly happens when the user enter the number?

Any error message etc?

Now you can use "async mode interactive" under the interrface group-async 1 with "login local" under the line config. The config should be very similar which is at following url and try after that.

http://www.cisco.com/warp/public/793/access_dial/async_ppp.html

Post the same debug if things still dosen't work

dcristoni · ‎04-28-2003

I modified the configuration.

I didn't see any error message in authentication and when i entered the number.

Now the outgoing call of callback start but the call drops after one ring.

Both User Nps and Test are configured.

Many Thanks.

Configuration

username test callback-dialstring "" password 0 cisco

username nps callback-dialstring "" password 0 cisco

memory-size iomem 40

modem call-record terse

modem country mica italy

ip subnet-zero

!

isdn switch-type basic-net3

chat-script offhook "" "ATH1" OK

chat-script callback ABORT ERROR ABORT BUSY "" "ATZ" OK "ATDT \T" TIMEOUT60 CONNECT \c

modemcap entry aster:MSC=&F&D2S0=0S34=18000S40=10S10=50debugthismodemS71=4

!

interface Loopback0

ip address 192.168.19.254 255.255.255.0

!

interface BRI1/0

no ip address

encapsulation ppp

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/1

no ip address

encapsulation ppp

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/2

no ip address

encapsulation ppp

shutdown

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface BRI1/3

no ip address

encapsulation ppp

shutdown

dialer pool-member 1

isdn switch-type basic-net3

isdn incoming-voice modem

no cdp enable

!

interface Ethernet3/0

ip address 192.168.10.10 255.255.255.0

half-duplex

no cdp enable

!

interface Group-Async1

ip unnumbered Loopback0

encapsulation ppp

ip tcp header-compression

no ip mroute-cache

async mode interactive

peer default ip address pool set

ppp callback permit

ppp authentication pap chap ms-chap

group-range 1 6

!

interface Dialer1

ip unnumbered Loopback0

encapsulation ppp

no ip mroute-cache

dialer-group 1

peer default ip address pool set

no fair-queue

no cdp enable

ppp authentication pap chap ms-chap

!

ip local pool set 192.168.19.12 192.168.19.241

ip classless

ip route 0.0.0.0 0.0.0.0 192.168.10.1

no ip http server

!

dialer-list 1 protocol ip permit

no cdp run

!

line con 0

line 1 6

no flush-at-activation

script modem-off-hook offhook

script callback callback

login local

modem InOut

modem autoconfigure type aster

transport input all

autoselect during-login

autoselect ppp

callback forced-wait 10

line aux 0

line vty 0

password cisco

login

length 25

line vty 1 4

password cisco

login

!

Debug

*Mar 1 00:24:43.903: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

*Mar 1 00:24:43.903: CHAT5: Matched chat script offhook to string offhook

*Mar 1 00:24:43.903: CHAT5: Asserting DTR

*Mar 1 00:24:43.903: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

*Mar 1 00:24:43.903: CHAT5: Chat script offhook started

*Mar 1 00:24:43.903: CHAT5: Sending string: ATH1

*Mar 1 00:24:43.903: CHAT5: Expecting string: OK

*Mar 1 00:24:43.939: CHAT5: Completed match for expect: OK

*Mar 1 00:24:43.939: CHAT5: Chat script offhook finished, status = Success

*Mar 1 00:24:43.939: CHAT5: Matched chat script callback to string callback

*Mar 1 00:24:43.939: CHAT5: Asserting DTR

*Mar 1 00:24:43.939: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

*Mar 1 00:24:43.939: CHAT5: Chat script callback started

*Mar 1 00:24:43.939: CHAT5: Sending string: ATZ

*Mar 1 00:24:43.939: CHAT5: Expecting string: OK

*Mar 1 00:24:43.971: CHAT5: Completed match for expect: OK

*Mar 1 00:24:43.971: CHAT5: Sending string: ATDT \T<0516398150>

*Mar 1 00:24:43.971: CHAT5: Expecting string: TIMEOUT60

*Mar 1 00:24:44.003: Modem 0/4 CSM: Called Number Rcvd = 0516398150

*Mar 1 00:24:44.003: Modem 0/4 CSM: (CSM_PROC_IDLE)<--MODEM_DIAL_OUT

*Mar 1 00:24:44.003: Modem 0/4 Mica: configured for Originate mode, with Null signaling, 0x1 tone detection.

*Mar 1 00:24:44.003: Modem 0/4 Mica: received dialstring 0516398150

*Mar 1 00:24:44.007: ISDN BR1/0: TX -> INFOc sapi=0 tei=64 ns=13 nr=9 i=0x0801020504038090A3180183700B8030353136333938313530

*Mar 1 00:24:44.007: SETUP pd = 8 callref = 0x02

*Mar 1 00:24:44.007: Bearer Capability i = 0x8090A3

*Mar 1 00:24:44.007: Channel ID i = 0x83

*Mar 1 00:24:44.011: Called Party Number i = 0x80, '0516398150', Plan:Unknown, Type:Unknown

*Mar 1 00:24:44.043: ISDN BR1/0: RX <- RRr sapi=0 tei=64 nr=14

*Mar 1 00:24:44.139: Modem 0/4 Mica: in modem state CALL_SETUP

*Mar 1 00:24:44.787: ISDN BR1/0: RX <- INFOc sapi=0 tei=64 ns=9 nr=14 i=0x0801820D1801891E028288

*Mar 1 00:24:44.791: SETUP_ACK pd = 8 callref = 0x82

*Mar 1 00:24:44.791: Channel ID i = 0x89

*Mar 1 00:24:44.791: Progress Ind i = 0x8288 - In-band info or appropriate now available

*Mar 1 00:24:44.791: ISDN BR1/0: TX -> RRr sapi=0 tei=64 nr=10

*Mar 1 00:24:44.795: CSM: MODEM_REPORT from 1/0:0, call_id=0x8007, event=0x2, cause=0x0, dchan_idb=0x6119ECFC

*Mar 1 00:24:44.795: Modem 0/4 CSM: (CSM_PROC_OC_ISDN_PROCESSING_CALL)<--ISDN_BCHAN_ASSIGNED

*Mar 1 00:24:46.247: ISDN BR1/0: RX <- INFOc sapi=0 tei=64 ns=10 nr=14 i=0x080182011E0284881E028182

*Mar 1 00:24:46.251: ALERTING pd = 8 callref = 0x82

*Mar 1 00:24:46.251: Progress Ind i = 0x8488 - In-band info or appropriate now available

*Mar 1 00:24:46.251: Progress Ind i = 0x8182 - Destination address is non-ISDN

*Mar 1 00:24:46.251: ISDN BR1/0: TX -> RRr sapi=0 tei=64 nr=11

*Mar 1 00:24:46.255: CSM: MODEM_REPORT from 1/0:0, call_id=0x8007, event=0x5, cause=0x0, dchan_idb=0x6119ECFC

*Mar 1 00:24:46.255: Modem 0/4 CSM: MODEM_REPORT rcvd DEV_CALL_PROGRESSING for call_id 0x8007

*Mar 1 00:24:46.255: Modem 0/4 CSM: (CSM_PROC_OC_ISDN_CONNECT_PENDING)<--ISDN_CALL_PROGRESSING

*Mar 1 00:24:47.583: ISDN BR1/0: RX <- INFOc sapi=0 tei=64 ns=11 nr=14 i=0x080182071E028182290503041C10024C0B2181353136333938313530

*Mar 1 00:24:47.583: CONNECT pd = 8 callref = 0x82

*Mar 1 00:24:47.583: Progress Ind i = 0x8182 - Destination address is non-ISDN

*Mar 1 00:24:47.587: Date/Time i = 0x03041C1002

*Mar 1 00:24:47.587: Connected Number i = 0x2181353136333938313530

*Mar 1 00:24:47.587: ISDN BR1/0: TX -> RRr sapi=0 tei=64 nr=12

*Mar 1 00:24:47.591: CSM: MODEM_REPORT from 1/0:0, call_id=0x8007, event=0x4, cause=0x0, dchan_idb=0x6119ECFC

*Mar 1 00:24:47.591: Modem 0/4 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0x8007

*Mar 1 00:24:47.591: Modem 0/4 CSM: (CSM_PROC_OC_ISDN_CONNECT_PENDING)<--ISDN_CONNECTED

*Mar 1 00:24:47.595: ISDN BR1/0: TX -> INFOc sapi=0 tei=64 ns=14 nr=12 i=0x0801020F

*Mar 1 00:24:47.595: CONNECT_ACK pd = 8 callref = 0x02

*Mar 1 00:24:47.615: ISDN BR1/0: RX <- RRr sapi=0 tei=64 nr=15

*Mar 1 00:24:47.623: Modem 0/4 Mica: in modem state CONNECT

*Mar 1 00:24:48.971: CHAT5: Timeout expecting: TIMEOUT60

*Mar 1 00:24:48.971: CHAT5: Chat script callback finished, status = Connection timed out; remote host not responding

*Mar 1 00:24:48.971: TTY5 Callback process chat script fail status=Connection timed out; remote host not responding

*Mar 1 00:24:48.971: TTY5: Line reset by "Callback Process"

*Mar 1 00:24:48.971: TTY5: Modem: (unknown)->HANGUP

*Mar 1 00:24:48.971: TTY5: no timer type 0 to destroy

*Mar 1 00:24:48.971: TTY5: no timer type 1 to destroy

*Mar 1 00:24:48.971: TTY5: no timer type 3 to destroy

*Mar 1 00:24:48.971: TTY5: no timer type 4 to destroy

*Mar 1 00:24:48.971: TTY5: no timer type 2 to destroy

*Mar 1 00:24:49.571: Modem 0/4 Mica: in modem state LINK

*Mar 1 00:24:49.959: TTY5: dropping DTR, hanging up

*Mar 1 00:24:49.959: Modem 0/4 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--ASYNC_DTR_DOWN

*Mar 1 00:24:49.959: tty5: Modem: HANGUP->IDLE

*Mar 1 00:24:49.967: Modem 0/4 Mica: in modem state TERMINATING

*Mar 1 00:24:49.983: Modem 0/4 CSM: (CSM_PROC_DISCONNECTED)<--MODEM_DISCONNECTED

*Mar 1 00:24:49.983: Modem 0/4 Mica: in modem state IDLE

*Mar 1 00:24:49.983: Modem 0/4 CSM: (CSM_PROC_DISCONNECTED)<--QUEUED_DISCONNECT

*Mar 1 00:24:50.015: Modem 0/4 CSM: CSM_MODEM_DEALLOCATE: modem is deallocated

*Mar 1 00:24:50.015: %ISDN-6-CONNECT: Interface BRI1/0:1 is now connected to unknown

*Mar 1 00:24:50.019: %ISDN-6-DISCONNECT: Interface BRI1/0:1 disconnected from unknown , call lasted 2 seconds

*Mar 1 00:24:50.019: ISDN BR1/0: TX -> INFOc sapi=0 tei=64 ns=15 nr=12 i=0x0801024508028090

*Mar 1 00:24:50.023: DISCONNECT pd = 8 callref = 0x02

*Mar 1 00:24:50.023: Cause i = 0x8090 - Normal call clearing

*Mar 1 00:24:50.023: Modem 0/4 Mica: DISCONNECT after 00:00:03, due to reason (0x7F03) Dropped DTR.

*Mar 1 00:24:50.023: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0 slot/contr/chan=1/0/0, slot/port=0/4, call_id=8007, calling=(n/a), called=516344501, time=3, finl-state=LINK, disc(modem)=7F03 Condition occurred during call setup/Requested by host/DTR dropped

*Mar 1 00:24:50.043: ISDN BR1/0: RX <- RRr sapi=0 tei=64 nr=16

*Mar 1 00:24:50.211: ISDN BR1/0: RX <- INFOc sapi=0 tei=64 ns=12 nr=16 i=0x0801824D

*Mar 1 00:24:50.215: RELEASE pd = 8 callref = 0x82

*Mar 1 00:24:50.215: ISDN BR1/0: TX -> RRr sapi=0 tei=64 nr=13

*Mar 1 00:24:50.219: CSM: MODEM_REPORT from 1/0:0, call_id=0x8007, event=0x0, cause=0x0, dchan_idb=0x6119ECFC

*Mar 1 00:24:50.219: CSM: MODEM_REPORT rcvd DEV_IDLE for call_id 0x8007, modem not found due to wrong b channel number or b channel is deallocated

*Mar 1 00:24:50.219: ISDN BR1/0: TX -> INFOc sapi=0 tei=64 ns=16 nr=13

Many Thanks

zahmed · ‎04-29-2003

In Chat script callback , make sure there is space between TIMEOUT and 60.

RIght now it looks like it is TIMEOUT60.

~Zulfi

dcristoni · ‎04-30-2003

Many thanks,the problem was really the space!

Now the callback works perfectly.

Marco