Callback to Windows98

[maraz]

Hello,

I have not found a solution regarding callback to Windows 98 and W2000. I have tested with Cisco 3640 with both 11.3 and 12.1 IOS. My error-messages is provided from a debug below. Is my problem related to bug CSCdj81013?

Aug 13 15:52:08.149: Modem 0/10 Mica: received dialstring 0230438

Aug 13 15:52:08.181: CSM: MODEM_REPORT from 2/0:30, call_id=0xA003, event=0x3, cause=0x0, dchan_idb=0x60FF0FC0

Aug 13 15:52:08.181: Modem 0/10 CSM: (CSM_PROC_OC_ISDN_PROCESSING_CALL)<--ISDN_BCHAN_ASSIGNED

Aug 13 15:52:08.213: Modem 0/10 Mica: in modem state CALL_SETUP

Aug 13 15:52:22.349: CSM: MODEM_REPORT from 2/0:30, call_id=0xA003, event=0x4, cause=0x0, dchan_idb=0x60FF0FC0

Aug 13 15:52:22.349: Modem 0/10 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0xA003

Aug 13 15:52:22.349: Modem 0/10 CSM: (CSM_PROC_OC_ISDN_CONNECT_PENDING)<--ISDN_CONNECTED

Aug 13 15:52:22.393: Modem 0/10 Mica: in modem state CONNECT

Aug 13 15:52:29.709: Modem 0/10 Mica: in modem state LINK

Aug 13 15:52:33.973: Modem 0/10 Mica: in modem state TERMINATING

Aug 13 15:52:34.009: Modem 0/10 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--MODEM_DISCONNECTED

Aug 13 15:52:34.009: Modem 0/10 Mica: in modem state IDLE

Aug 13 15:52:34.013: Modem 0/10 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--QUEUED_DISCONNECT

Aug 13 15:52:34.037: Modem 0/10 Mica: DISCONNECT after 00:00:12, due to reason (0x6104) No end of answer-back tone.

Aug 13 15:52:34.249: Se2/0:30 LCP: State is Closed

Aug 13 15:52:34.249: Se2/0:30 PPP: Phase is DOWN

Aug 13 15:52:38.109: CHAT11: Timeout expecting: CONNECT

Aug 13 15:52:38.109: CHAT11: Chat script CALLMEBACK finished, status = Connection timed out; remote host not responding

Aug 13 15:52:38.109: TTY11: Line reset by "Callback Process"

Aug 13 15:52:38.109: TTY11: Modem: READY->HANGUP

Aug 13 15:52:39.069: TTY11: dropping DTR, hanging up

Aug 13 15:52:39.069: Modem 0/10 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

Aug 13 15:52:39.069: tty11: Modem: HANGUP->IDLE

[tepatel]

We need to see the following debug for a call to find the exact probelm.

debug modem

debug modem csm

debug callback

debug dialer

debug ppp authentication

debug ppp negotiation

debug ppp cbcp

term mon

Along with running config.

[maraz]

Hello,

The configuration is:

version 11.3

service timestamps debug datetime msec localtime

service timestamps log datetime msec localtime

service password-encryption

!

hostname pronova_3640

!

aaa new-model

aaa authentication login default tacacs+ enable local

aaa authentication ppp tacplus tacacs+

aaa authorization exec default if-authenticated tacacs+

aaa authorization network default tacacs+

aaa accounting network netuse start-stop tacacs+

enable secret 5 $1$LbRG$4JkzH614Ad26lcTr/cZd70

!

username dotcom password 7 15190A025621202D

memory-size iomem 15

ip subnet-zero

no ip source-route

no ip finger

ip host pix 172.26.1.2

ip host gts 213.187.208.253

ip name-server 213.187.209.252

virtual-profile aaa

isdn switch-type primary-net5

chat-script CALLBACK ABORT ERROR ABORT BUSY "" "AT" OK "ATDT \T" TIMEOUT 30 CONNECT \c

chat-script offhook "" "ATH1" OK \c

chat-script callme ABORT ERROR ABORT BUSY "" "ATZ" OK "ATDT \T" TIMEOUT 30 CONNECT \c

!

clock timezone MET 1

clock summer-time MET recurring last Sun Mar 2:00 last Sun Oct 2:00

!

!

controller E1 2/0

framing NO-CRC4

pri-group timeslots 1-31

!

!

process-max-time 200

!

interface Loopback0

ip address 172.26.200.254 255.255.255.0

ip broadcast-address 172.26.200.255

no ip directed-broadcast

!

interface FastEthernet1/0

no ip address

ip broadcast-address 10.10.10.255

no ip directed-broadcast

full-duplex

!

!

interface Serial2/0:15

description 0114424943

no ip address

no ip directed-broadcast

encapsulation ppp

isdn switch-type primary-net5

isdn incoming-voice modem

ppp authentication chap tacplus

!

interface Group-Async1

ip unnumbered Loopback0

no ip directed-broadcast

encapsulation ppp

ip tcp header-compression passive

async mode interactive

peer default ip address pool test

no cdp enable

ppp callback accept

ppp authentication chap tacplus

group-range 1 12

!

ip local pool test 172.26.200.200 172.26.200.253

tacacs-server host 172.26.0.10

tacacs-server key radiogold949

snmp-server community propub RO 10

snmp-server community propri RW 10

banner motd ^C

Welcome to "pronova_3640". Autherized personel only!

All login attempts are logged!^C

!

line con 0

transport input none

line 1 12

no flush-at-activation

autoselect during-login

autoselect ppp

script modem-off-hook offhook

script callback callme

modem InOut

transport preferred none

transport input all

transport output none

callback forced-wait 10

line aux 0

line vty 0 4

access-class 10 in

exec-timeout 5 0

!

ntp clock-period 17179758

ntp server 192.36.144.23

end

The debug is:

pronova_3640#

Aug 30 17:00:48.215: CSM: MODEM_REPORT from 2/0:3, call_id=0x1D, event=0x1, cause=0x0, dchan_idb=0x60FF0FC0

Aug 30 17:00:48.215: CSM: Next free modem = 0/4; statbits = 10020

Aug 30 17:00:48.215: Modem 0/4 CSM: modem is allocated, modems free=11

Aug 30 17:00:48.215: Modem 0/4 CSM: Incoming call from 11230426 to Unknown, id 0x1D

Aug 30 17:00:48.215: Modem 0/4 CSM: (CSM_PROC_IDLE)<--ISDN_CALL

Aug 30 17:00:48.303: CSM: MODEM_REPORT from 2/0:3, call_id=0x1D, event=0x4, cause=0x0, dchan_idb=0x60FF0FC0

Aug 30 17:00:48.303: Modem 0/4 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0x1D

Aug 30 17:00:48.303: Modem 0/4 CSM: (CSM_PROC_MODEM_RESERVED)<--ISDN_CONNECTED

Aug 30 17:00:48.303: Modem 0/4 Mica: configured for Answer mode, with Null signaling, 0x0 tone detection.

Aug 30 17:00:48.471: Modem 0/4 Mica: in modem state CALL_SETUP

Aug 30 17:00:48.495: Modem 0/4 Mica: in modem state CONNECT

Aug 30 17:00:48.899: Modem 0/4 Mica: in modem state LINK

Aug 30 17:00:58.875: Modem 0/4 Mica: in modem state TRAINUP

Aug 30 17:01:00.943: Modem 0/4 Mica: in modem state EC_NEGOTIATING

Aug 30 17:01:01.371: Modem 0/4 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--MODEM_CONNECTED

Aug 30 17:01:01.371: Modem 0/4 Mica: in modem state STEADY

Aug 30 17:01:01.387: Modem 0/4 Mica: CONNECT at 33600/28800 (Tx/Rx), V34+, LAPM, V42bis

Aug 30 17:01:02.127: TTY5: DSR came up

Aug 30 17:01:02.127: tty5: Modem: IDLE->READY

Aug 30 17:01:02.135: TTY5: EXEC creation

Aug 30 17:01:04.583: TTY5: Autoselect(2) sample 7E

Aug 30 17:01:04.583: TTY5: Autoselect(2) sample 7EFF

Aug 30 17:01:04.583: TTY5: Autoselect(2) sample 7EFF7D

Aug 30 17:01:04.583: TTY5: Autoselect(2) sample 7EFF7D23

Aug 30 17:01:04.583: TTY5 Autoselect cmd: ppp negotiate

Aug 30 17:01:04.583: TTY5: EXEC creation

Aug 30 17:01:05.091: As5 LCP: I CONFREQ [Closed] id 2 len 23

Aug 30 17:01:05.091: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

Aug 30 17:01:05.091: As5 LCP: MagicNumber 0x008B5CD2 (0x0506008B5CD2)

Aug 30 17:01:05.091: As5 LCP: PFC (0x0702)

Aug 30 17:01:05.091: As5 LCP: ACFC (0x0802)

Aug 30 17:01:05.091: As5 LCP: Callback 6 (0x0D0306)

Aug 30 17:01:05.091: As5 LCP: Lower layer not up, Fast Starting

Aug 30 17:01:05.091: As5 PPP: Treating connection as a dedicated line

Aug 30 17:01:05.091: As5 PPP: Phase is ESTABLISHING, Active Open

Aug 30 17:01:05.091: Modem 0/4 Mica: PPP escape_map: Tx map = FFFFFFFF, Rx map = 0

Aug 30 17:01:05.091: As5 LCP: O CONFREQ [Closed] id 12 len 25

Aug 30 17:01:05.095: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

Aug 30 17:01:05.095: As5 LCP: AuthProto CHAP (0x0305C22305)

Aug 30 17:01:05.095: As5 LCP: MagicNumber 0x1BEBA0AA (0x05061BEBA0AA)

Aug 30 17:01:05.095: As5 LCP: PFC (0x0702)

Aug 30 17:01:05.095: As5 LCP: ACFC (0x0802)

Aug 30 17:01:05.095: As5 LCP: O CONFACK [REQsent] id 2 len 23

Aug 30 17:01:05.095: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

Aug 30 17:01:05.095: As5 LCP: MagicNumber 0x008B5CD2 (0x0506008B5CD2)

Aug 30 17:01:05.095: As5 LCP: PFC (0x0702)

Aug 30 17:01:05.095: As5 LCP: ACFC (0x0802)

Aug 30 17:01:05.095: As5 LCP: Callback 6 (0x0D0306)

Aug 30 17:01:05.095: %LINK-3-UPDOWN: Interface Async5, changed state to up

Aug 30 17:01:05.271: As5 LCP: I CONFACK [ACKsent] id 12 len 25

Aug 30 17:01:05.271: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

Aug 30 17:01:05.271: As5 LCP: AuthProto CHAP (0x0305C22305)

Aug 30 17:01:05.271: As5 LCP: MagicNumber 0x1BEBA0AA (0x05061BEBA0AA)

Aug 30 17:01:05.271: As5 LCP: PFC (0x0702)

Aug 30 17:01:05.271: As5 LCP: ACFC (0x0802)

Aug 30 17:01:05.271: As5 LCP: State is Open

Aug 30 17:01:05.271: Modem 0/4 Mica: PPP escape_map: Tx map = A0000, Rx map = 0

Aug 30 17:01:05.271: As5 MCB: Initialize

Aug 30 17:01:05.271: As5 MCB: Flush

Aug 30 17:01:05.271: As5 PPP: Phase is AUTHENTICATING, by this end

Aug 30 17:01:05.275: As5 CHAP: O CHALLENGE id 5 len 33 from "pronova_3640"

Aug 30 17:01:05.395: As5 CHAP: I RESPONSE id 5 len 25 from "roma"

Aug 30 17:01:05.803: As5 CHAP: O SUCCESS id 5 len 4

Aug 30 17:01:05.803: As5 MCB: Start

Aug 30 17:01:05.803: As5 MCB: User roma Callback Number - Server 0230426

Aug 30 17:01:05.803: As5 MCB: Newstate 0-INIT -> 2-WAIT_RESPONSE

Aug 30 17:01:05.803: Async5 PPP: O MCB Request(1) id 3 len 7

Aug 30 17:01:05.807: Async5 MCB: O 1 3 0 7 3 3 0

Aug 30 17:01:05.807: As5 MCB: O Request Id 3 Callback Type Server-Num delay 0

Aug 30 17:01:05.807: As5 PPP: Phase is CBCP

Aug 30 17:01:06.155: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async5, changed state to up

Aug 30 17:01:07.135: Async5 PPP: I MCB Response(2) id 3 len 7

Aug 30 17:01:07.135: Async5 MCB: I 2 3 0 7 3 3 F

Aug 30 17:01:07.135: As5 MCB: Received response

Aug 30 17:01:07.135: As5 MCB: Response CBK-Server-Num 3 3 15

Aug 30 17:01:07.135: Async5 PPP: O MCB Ack(3) id 4 len 7

Aug 30 17:01:07.135: Async5 MCB: O 3 4 0 7 3 3 F

Aug 30 17:01:07.135: As5 MCB: O Ack Id 4 Callback Type Server-Num delay 15

Aug 30 17:01:07.135: As5 MCB: Negotiated MCB with peer

Aug 30 17:01:07.135: As5 MCB: Newstate 2-WAIT_RESPONSE -> 3-WAIT_TERMINATE

Aug 30 17:01:07.243: As5 LCP: I TERMREQ [Open] id 3 len 4

Aug 30 17:01:07.243: As5 LCP: O TERMACK [Open] id 3 len 4

Aug 30 17:01:07.243: As5 MCB: Peer terminating the link

Aug 30 17:01:07.243: As5 MCB: Newstate 3-WAIT_TERMINATE -> 5-WAIT_LINKDOWN

Aug 30 17:01:07.243: As5 PPP: Phase is TERMINATING

Aug 30 17:01:07.243: As5 MCB: Link terminated by peer, Callback Needed

Aug 30 17:01:07.243: As5 MCB: Newstate 5-WAIT_LINKDOWN -> 6-CALLING

Aug 30 17:01:07.243: As5 MCB: Initiate Callback for roma at 0230426 using Async

Aug 30 17:01:07.247: As5 MCB: Async-callback in progress

Aug 30 17:01:07.247: TTY5 Callback PPP process creation

Aug 30 17:01:07.247: As5 AAA/ACCT: Using PPP accounting list ""

Aug 30 17:01:07.247: TTY5 Callback process initiated, user: dialstring 0230426

Aug 30 17:01:07.455: Modem 0/4 Mica: in modem state TERMINATING

Aug 30 17:01:07.519: Modem 0/4 CSM: (CSM_PROC_CONNECTED)<--MODEM_DISCONNECTED

Aug 30 17:01:07.519: Modem 0/4 Mica: in modem state IDLE

Aug 30 17:01:07.519: Modem 0/4 CSM: (CSM_PROC_CONNECTED)<--QUEUED_DISCONNECT

Aug 30 17:01:07.547: Modem 0/4 Mica: DISCONNECT after 00:00:19, due to reason (0xA220) EC rcvd DISC frame.

Aug 30 17:01:07.735: Se2/0:3 LCP: State is Closed

Aug 30 17:01:07.735: Se2/0:3 PPP: Phase is DOWN

Aug 30 17:01:07.735: Serial2/0:3: disconnecting call

Aug 30 17:01:08.175: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async5, changed state to down

Aug 30 17:01:09.247: TTY5: Async Int reset: Dropping DTR

Aug 30 17:01:09.247: Modem 0/4 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

Aug 30 17:01:10.183: As5 LCP: TIMEout: Time 0xB702038 State TERMsent

Aug 30 17:01:10.183: As5 LCP: State is Closed

Aug 30 17:01:10.183: As5 PPP: Phase is DOWN

Aug 30 17:01:10.183: As5 PPP: Phase is ESTABLISHING, Passive Open

Aug 30 17:01:10.183: Modem 0/4 Mica: PPP escape_map: Tx map = FFFFFFFF, Rx map = 0

Aug 30 17:01:10.183: As5 LCP: State is Listen

Aug 30 17:01:11.247: %LINK-5-CHANGED: Interface Async5, changed state to reset

Aug 30 17:01:11.247: As5 LCP: State is Closed

Aug 30 17:01:11.247: As5 PPP: Phase is DOWN

Aug 30 17:01:11.251: As5 IPCP: Remove route to 172.26.200.224

Aug 30 17:01:14.247: Modem 0/4 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

Aug 30 17:01:14.247: TTY5 Callback forced wait = 10 seconds

Aug 30 17:01:16.247: %LINK-3-UPDOWN: Interface Async5, changed state to down

Aug 30 17:01:16.247: As5 LCP: State is Closed

Aug 30 17:01:16.247: As5 PPP: Phase is DOWN

Aug 30 17:01:24.247: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

Aug 30 17:01:24.247: CHAT5: Asserting DTR

Aug 30 17:01:24.247: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

Aug 30 17:01:24.247: CHAT5: Chat script offhook started

Aug 30 17:01:24.283: CHAT5: Chat script offhook finished, status = Success

Aug 30 17:01:24.283: CHAT5: Asserting DTR

Aug 30 17:01:24.283: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

Aug 30 17:01:24.283: CHAT5: Chat script callme started

Aug 30 17:01:24.359: Modem 0/4 CSM: Called Number Rcvd = 0230426

Aug 30 17:01:24.359: Modem 0/4 CSM: (CSM_PROC_IDLE)<--MODEM_DIAL_OUT

Aug 30 17:01:24.359: Modem 0/4 Mica: configured for Originate mode, with Null signaling, 0x1 tone detection.

Aug 30 17:01:24.359: Modem 0/4 Mica: received dialstring 0230426

Aug 30 17:01:24.403: CSM: MODEM_REPORT from 2/0:30, call_id=0xA017, event=0x3, cause=0x0, dchan_idb=0x60FF0FC0

Aug 30 17:01:24.403: Modem 0/4 CSM: (CSM_PROC_OC_ISDN_PROCESSING_CALL)<--ISDN_BCHAN_ASSIGNED

Aug 30 17:01:24.455: Modem 0/4 Mica: in modem state CALL_SETUP

Aug 30 17:01:35.746: CSM: MODEM_REPORT from 2/0:30, call_id=0xA017, event=0x4, cause=0x0, dchan_idb=0x60FF0FC0

Aug 30 17:01:35.746: Modem 0/4 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0xA017

Aug 30 17:01:35.746: Modem 0/4 CSM: (CSM_PROC_OC_ISDN_CONNECT_PENDING)<--ISDN_CONNECTED

Aug 30 17:01:35.786: Modem 0/4 Mica: in modem state CONNECT

Aug 30 17:01:43.834: Modem 0/4 Mica: in modem state LINK

Aug 30 17:01:48.098: Modem 0/4 Mica: in modem state TERMINATING

Aug 30 17:01:48.134: Modem 0/4 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--MODEM_DISCONNECTED

Aug 30 17:01:48.138: Modem 0/4 Mica: in modem state IDLE

Aug 30 17:01:48.138: Modem 0/4 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--QUEUED_DISCONNECT

Aug 30 17:01:48.162: Modem 0/4 Mica: DISCONNECT after 00:00:12, due to reason (0x6104) No end of answer-back tone.

Aug 30 17:01:48.346: Se2/0:30 LCP: State is Closed

Aug 30 17:01:48.346: Se2/0:30 PPP: Phase is DOWN

Aug 30 17:01:48.346: Serial2/0:30: disconnecting call

Aug 30 17:01:54.326: CHAT5: Chat script callme finished, status = Connection timed out; remote host not responding

Aug 30 17:01:54.326: TTY5 Callback process chat script fail status=Connection timed out; remote host not responding

Aug 30 17:01:54.326: TTY5: Line reset by "Callback Process"

Aug 30 17:01:54.326: TTY5: Modem: READY->HANGUP

Aug 30 17:01:55.214: TTY5: dropping DTR, hanging up

Aug 30 17:01:55.214: Modem 0/4 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

Aug 30 17:01:55.214: tty5: Modem: HANGUP->IDLE

Aug 30 17:02:00.218: TTY5: restoring DTR

Aug 30 17:02:00.218: Modem 0/4 CSM: received ASYNC_DTR_UP for line 5

[mljohnson]

Here is the problem:

Aug 30 17:01:43.834: Modem 0/4 Mica: in modem state LINK

Aug 30 17:01:48.098: Modem 0/4 Mica: in modem state TERMINATING

Aug 30 17:01:48.162: Modem 0/4 Mica: DISCONNECT after 00:00:12, due to reason (0x6104) No end of answer-back tone.

I would first suggest you upgrade the modem code, if not the IOS, to the latest to ensure this is not a modem bug on our end.

You can find out more info about this disconnect code here:

http://www.cisco.com/warp/public/76/mica-states-drs.html#MICA_DISCONNECT

[brianthompson]

This may sound a bit simplistic but have you tried changing the timeout parameter on your chat script from 30 to 60. I had this problem on a 2620 and solved it by increasing the timeout. Give it a try - can't hurt.