08-26-2002 10:46 PM - edited 03-02-2019 12:56 AM
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
08-28-2002 08:25 AM
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.
08-30-2002 07:09 AM
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
09-18-2002 03:18 PM
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
09-20-2002 11:50 AM
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.
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide