CallBack Problem with 2509

[jpcastro]

I've got the following problem with my callback configuration:

1) Dial-up with Windows 2000

2) The router answer the call and authenticate the user

3) The PC wait for the callback

4) The router dials to the PC

5) The PC answer the call

6) The PC can't authenticate user, the message "Verifying username and password" remains until error 619 comes. "The specific port...."

Here goes the config

version 12.0

service timestamps debug uptime

service timestamps log uptime

service password-encryption

!

hostname AS2509

!

aaa new-model

aaa authentication login default none

aaa authentication login use-local local

aaa authentication ppp default local

aaa authorization network default local

enable secret 5 $1$hLuh$A/KGbGt25g8I073GpT1tN/

enable password 7 030752180500

!

username znoopydog callback-dialstring 2390 password 7 07152F43411900011815

username cisco password 7 1511021F0725

ip subnet-zero

ip name-server 172.20.1.4

chat-script offhook "" "ATH1" OK

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

!

!

!

interface Ethernet0

ip address 172.80.10.11 255.255.0.0

no ip directed-broadcast

shutdown

no cdp enable

!

interface Serial0

no ip address

no ip directed-broadcast

no ip mroute-cache

shutdown

no fair-queue

!

interface Serial1

no ip address

no ip directed-broadcast

shutdown

no cdp enable

!

interface Group-Async1

ip unnumbered Ethernet0

no ip directed-broadcast

encapsulation ppp

ip tcp header-compression passive

async mode interactive

peer default ip address pool setup_pool

no fair-queue

ppp max-bad-auth 10

ppp callback accept

ppp authentication chap

ppp multilink

group-range 1 8

!

ip local pool setup_pool 172.80.100.100 172.80.100.110

ip classless

ip route 0.0.0.0 0.0.0.0 172.80.0.1

!

access-list 105 permit ip any any

dialer-list 5 protocol ip list 105

!

line con 0

exec-timeout 0 0

transport input none

line 1 8

session-timeout 20

autoselect during-login

autoselect ppp

script modem-off-hook offhook

script callback callback

login authentication use-local

modem InOut

modem autoconfigure discovery

transport preferred none

transport input all

transport output none

callback forced-wait 10

stopbits 1

speed 38400

flowcontrol hardware

line aux 0

line vty 0 4

password 7 01100F175804

!

end

1d13h: %LINK-5-CHANGED: Interface Async5, changed state to reset

1d13h: %LINK-3-UPDOWN: Interface Async5, changed state to down

1d14h: %LINK-3-UPDOWN: Interface Async5, changed state to up

1d14h: As5 AAA/ACCT: Using PPP accounting list ""

1d14h: %LINK-5-CHANGED: Interface Async5, changed state to reset

1d14h: %LINK-3-UPDOWN: Interface Async5, changed state to down

1d14h: TTY5: timer_create_bg error

1d14h: %LINK-3-UPDOWN: Interface Async5, changed state to up

1d14h: %LINK-5-CHANGED: Interface Async5, changed state to reset

1d14h: %LINK-3-UPDOWN: Interface Async5, changed state to down

Any Ideas?

Regards,

Juan Castro

[tepatel]

Here is the sample config for callback between router and windoes PC.

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

Now, if it deosn't work, we need to have a debug for following from the router to see where the issue can be.

debug ppp negotiation

debug modem

debug ppp cbcp

debug callback

debug aaa authorization

[jpcastro]

Debugs.

08:16:01: TTY4: autoconfigure probe started

08:16:09: TTY7: autoconfigure probe started

08:16:09: TTY6: autoconfigure probe started

08:16:09: TTY2: autoconfigure probe started

08:16:11: TTY3: autoconfigure probe started

08:16:17: TTY1: autoconfigure probe started

08:16:17: TTY8: autoconfigure probe started

08:16:27: TTY4: autoconfigure probe started

08:16:35: TTY7: autoconfigure probe started

08:16:35: TTY6: autoconfigure probe started

08:16:35: TTY2: autoconfigure probe started

08:16:37: TTY3: autoconfigure probe started

08:16:39: TTY5: DSR came up

08:16:39: tty5: Modem: IDLE->READY

08:16:39: TTY5: EXEC creation

08:16:39: TTY5: set timer type 10, 30 seconds

08:16:40: TTY5: Autoselect(2) sample 7E

08:16:40: TTY5: Autoselect(2) sample 7EFF

08:16:40: TTY5: Autoselect(2) sample 7EFF7D

08:16:40: TTY5: Autoselect(2) sample 7EFF7D23

08:16:40: TTY5 Autoselect cmd: ppp negotiate

08:16:40: TTY5: EXEC creation

08:16:40: TTY5: create timer type 1, 600 seconds

08:16:40: TTY5: destroy timer type 1 (OK)

08:16:40: TTY5: destroy timer type 0

08:16:40: TTY5: create timer type 2, 1200 seconds

08:16:42: TTY1: autoconfigure probe started

08:16:42: %LINK-3-UPDOWN: Interface Async5, changed state to up

08:16:42: As5 PPP: Treating connection as a dedicated line

08:16:42: As5 PPP: Phase is ESTABLISHING, Active Open

08:16:42: As5 LCP: O CONFREQ [Closed] id 178 len 25

08:16:42: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:16:42: As5 LCP: AuthProto CHAP (0x0305C22305)

08:16:42: As5 LCP: MagicNumber 0x521B4146 (0x0506521B4146)

08:16:42: As5 LCP: PFC (0x0702)

08:16:42: As5 LCP: ACFC (0x0802)

08:16:42: As5 LCP: I CONFACK [REQsent] id 178 len 25

08:16:42: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:16:42: As5 LCP: AuthProto CHAP (0x0305C22305)

08:16:42: As5 LCP: MagicNumber 0x521B4146 (0x0506521B4146)

08:16:42: As5 LCP: PFC (0x0702)

08:16:42: As5 LCP: ACFC (0x0802)

08:16:43: TTY8: autoconfigure probe started

08:16:43: As5 LCP: I CONFREQ [ACKrcvd] id 2 len 50

08:16:43: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:16:43: As5 LCP: MagicNumber 0x726F60A6 (0x0506726F60A6)

08:16:43: As5 LCP: PFC (0x0702)

08:16:43: As5 LCP: ACFC (0x0802)

08:16:43: As5 LCP: Callback 6 (0x0D0306)

08:16:43: As5 LCP: MRRU 1614 (0x1104064E)

08:16:43: As5 LCP: EndpointDisc 1 Local

08:16:43: As5 LCP: (0x1317015DF477464F9E43ADB6C56CCEA3)

08:16:43: As5 LCP: (0xE83D4900000000)

08:16:43: As5 LCP: O CONFREJ [ACKrcvd] id 2 len 31

08:16:43: As5 LCP: MRRU 1614 (0x1104064E)

08:16:43: As5 LCP: EndpointDisc 1 Local

08:16:43: As5 LCP: (0x1317015DF477464F9E43ADB6C56CCEA3)

08:16:43: As5 LCP: (0xE83D4900000000)

08:16:43: As5 LCP: I CONFREQ [ACKrcvd] id 3 len 23

08:16:43: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:16:43: As5 LCP: MagicNumber 0x726F60A6 (0x0506726F60A6)

08:16:43: As5 LCP: PFC (0x0702)

08:16:43: As5 LCP: ACFC (0x0802)

08:16:43: As5 LCP: Callback 6 (0x0D0306)

08:16:43: As5 LCP: O CONFACK [ACKrcvd] id 3 len 23

08:16:43: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:16:43: As5 LCP: MagicNumber 0x726F60A6 (0x0506726F60A6)

08:16:43: As5 LCP: PFC (0x0702)

08:16:43: As5 LCP: ACFC (0x0802)

08:16:43: As5 LCP: Callback 6 (0x0D0306)

08:16:43: As5 LCP: State is Open

08:16:43: As5 PPP: Phase is AUTHENTICATING, by this end

08:16:43: As5 CHAP: O CHALLENGE id 35 len 27 from "AS2509"

08:16:43: As5 LCP: I IDENTIFY [Open] id 4 len 18 magic 0x726F60A6 MSRASV5.00

08:16:43: As5 LCP: I IDENTIFY [Open] id 5 len 24 magic 0x726F60A6 MSRAS-1-THINKPAD

08:16:43: As5 CHAP: I RESPONSE id 35 len 30 from "znoopydog"

08:16:43: As5 CHAP: O SUCCESS id 35 len 4

08:16:43: As5 MCB: User znoopydog Callback Number - Server 2390

08:16:44: Async5 PPP: O MCB Request(1) id 56 len 7

08:16:44: Async5 MCB: O 1 38 0 7 3 3 0

08:16:44: As5 MCB: O Request Id 56 Callback Type Server-Num delay 0

08:16:44: As5 PPP: Phase is CBCP

08:16:44: Async5 PPP: I MCB Response(2) id 56 len 7

08:16:44: Async5 MCB: I 2 38 0 7 3 3 C

08:16:44: As5 MCB: Received response

08:16:44: As5 MCB: Response CBK-Server-Num 3 3 12

08:16:44: Async5 PPP: O MCB Ack(3) id 57 len 7

08:16:44: Async5 MCB: O 3 39 0 7 3 3 C

08:16:44: As5 MCB: O Ack Id 57 Callback Type Server-Num delay 12

08:16:44: As5 MCB: Negotiated MCB with peer

08:16:44: As5 LCP: I TERMREQ [Open] id 6 len 16 (0x726F60A6003CCD7400000000)

08:16:44: As5 LCP: O TERMACK [Open] id 6 len 4

08:16:44: As5 MCB: Peer terminating the link

08:16:44: As5 PPP: Phase is TERMINATING

08:16:44: As5 MCB: Link terminated by peer, Callback Needed

08:16:44: As5 MCB: Initiate Callback for znoopydog at 2390 using Async

08:16:44: As5 MCB: Async-callback in progress

08:16:44: As5 AAA/ACCT: Using PPP accounting list ""

08:16:46: As5 LCP: TIMEout: State TERMsent

08:16:46: As5 LCP: State is Closed

08:16:46: As5 PPP: Phase is DOWN

08:16:46: TTY5: Async Int reset: Dropping DTR

08:16:46: As5 PPP: Phase is ESTABLISHING, Passive Open

08:16:46: As5 LCP: State is Listen

08:16:48: %LINK-5-CHANGED: Interface Async5, changed state to reset

08:16:48: As5 LCP: State is Closed

08:16:48: As5 PPP: Phase is DOWN

08:16:48: As5 IPCP: Remove route to 172.80.100.100

08:16:52: TTY4: autoconfigure probe started

08:16:53: %LINK-3-UPDOWN: Interface Async5, changed state to down

08:16:53: As5 LCP: State is Closed

08:16:53: As5 PPP: Phase is DOWN

08:17:00: TTY2: autoconfigure probe started

08:17:00: TTY6: autoconfigure probe started

08:17:00: TTY7: autoconfigure probe started

08:17:01: CHAT5: Asserting DTR

08:17:01: CHAT5: Asserting DTR

08:17:02: TTY3: autoconfigure probe started

08:17:07: TTY1: autoconfigure probe started

08:17:08: TTY8: autoconfigure probe started

08:17:17: TTY4: autoconfigure probe started

08:17:23: TTY5: destroy timer type 1

08:17:23: TTY5: destroy timer type 0

08:17:23: TTY5: create timer type 2, 1200 seconds

08:17:23: TTY5: timer_create_bg error

08:17:25: %LINK-3-UPDOWN: Interface Async5, changed state to up

08:17:25: As5 PPP: Treating connection as a dedicated line

08:17:25: As5 PPP: Phase is ESTABLISHING, Active Open

08:17:25: As5 LCP: O CONFREQ [Closed] id 179 len 25

08:17:25: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:25: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:25: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:25: As5 LCP: PFC (0x0702)

08:17:25: As5 LCP: ACFC (0x0802)

08:17:26: TTY2: autoconfigure probe started

08:17:26: TTY7: autoconfigure probe started

08:17:26: TTY6: autoconfigure probe started

08:17:27: As5 LCP: TIMEout: State REQsent

08:17:27: As5 LCP: O CONFREQ [REQsent] id 180 len 25

08:17:27: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:27: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:27: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:27: As5 LCP: PFC (0x0702)

08:17:27: As5 LCP: ACFC (0x0802)

08:17:28: TTY3: autoconfigure probe started

08:17:29: As5 LCP: TIMEout: State REQsent

08:17:29: As5 LCP: O CONFREQ [REQsent] id 181 len 25

08:17:29: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:29: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:29: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:29: As5 LCP: PFC (0x0702)

08:17:29: As5 LCP: ACFC (0x0802)

08:17:31: As5 LCP: TIMEout: State REQsent

08:17:31: As5 LCP: O CONFREQ [REQsent] id 182 len 25

08:17:31: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:31: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:31: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:31: As5 LCP: PFC (0x0702)

08:17:31: As5 LCP: ACFC (0x0802)

08:17:32: TTY1: autoconfigure probe started

08:17:33: TTY8: autoconfigure probe started

08:17:33: As5 LCP: TIMEout: State REQsent

08:17:33: As5 LCP: O CONFREQ [REQsent] id 183 len 25

08:17:33: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:33: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:33: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:33: As5 LCP: PFC (0x0702)

08:17:33: As5 LCP: ACFC (0x0802)

08:17:35: As5 LCP: TIMEout: State REQsent

08:17:35: As5 LCP: O CONFREQ [REQsent] id 184 len 25

08:17:35: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:35: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:35: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:35: As5 LCP: PFC (0x0702)

08:17:35: As5 LCP: ACFC (0x0802)

08:17:37: As5 LCP: TIMEout: State REQsent

08:17:37: As5 LCP: O CONFREQ [REQsent] id 185 len 25

08:17:37: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:37: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:37: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:37: As5 LCP: PFC (0x0702)

08:17:37: As5 LCP: ACFC (0x0802)

08:17:39: As5 LCP: TIMEout: State REQsent

08:17:39: As5 LCP: O CONFREQ [REQsent] id 186 len 25

08:17:39: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:39: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:39: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:39: As5 LCP: PFC (0x0702)

08:17:40: As5 LCP: ACFC (0x0802)

08:17:42: As5 LCP: TIMEout: State REQsent

08:17:42: As5 LCP: O CONFREQ [REQsent] id 187 len 25

08:17:42: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:42: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:42: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:42: As5 LCP: PFC (0x0702)

08:17:42: As5 LCP: ACFC (0x0802)

08:17:43: TTY4: autoconfigure probe started

08:17:44: As5 LCP: TIMEout: State REQsent

08:17:44: As5 LCP: O CONFREQ [REQsent] id 188 len 25

08:17:44: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:44: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:44: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:44: As5 LCP: PFC (0x0702)

08:17:44: As5 LCP: ACFC (0x0802)

08:17:46: As5 LCP: TIMEout: State REQsent

08:17:46: As5 LCP: O CONFREQ [REQsent] id 189 len 25

08:17:46: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:17:46: As5 LCP: AuthProto CHAP (0x0305C22305)

08:17:46: As5 LCP: MagicNumber 0x521BEA01 (0x0506521BEA01)

08:17:46: As5 LCP: PFC (0x0702)

08:17:46: As5 LCP: ACFC (0x0802)

08:17:48: As5 LCP: TIMEout: State REQsent

08:17:48: TTY5: Async Int reset: Dropping DTR

08:17:48: As5 LCP: State is Listen

08:17:49: TTY5: DSR was dropped

08:17:49: tty5: Modem: READY->HANGUP

08:17:50: %LINK-5-CHANGED: Interface Async5, changed state to reset

08:17:50: As5 LCP: State is Closed

08:17:50: As5 PPP: Phase is DOWN

08:17:50: TTY5: dropping DTR, hanging up

08:17:50: tty5: Modem: HANGUP->IDLE

08:17:51: TTY5: cleanup pending. Delaying DTR

08:17:52: TTY5: cleanup pending. Delaying DTR

08:17:52: TTY2: autoconfigure probe started

08:17:52: TTY7: autoconfigure probe started

08:17:52: TTY6: autoconfigure probe started

08:17:53: TTY5: destroy timer type 0

08:17:53: TTY5: destroy timer type 1

08:17:53: TTY5: destroy timer type 3

08:17:53: TTY5: destroy timer type 4

08:17:53: TTY5: destroy timer type 2 (OK)

08:17:53: Async5: allowing modem_process to continue hangup

08:17:54: TTY5: restoring DTR

08:17:54: TTY5: autoconfigure probe started

08:17:54: TTY3: autoconfigure probe started

08:17:55: %LINK-3-UPDOWN: Interface Async5, changed state to down

08:17:55: As5 LCP: State is Closed

08:17:55: As5 PPP: Phase is DOWN

08:17:58: TTY1: autoconfigure probe started

08:17:59: TTY8: autoconfigure probe started

AS2509#

08:18:17: TTY2: autoconfigure probe started

08:18:17: TTY7: autoconfigure probe started

08:18:17: TTY6: autoconfigure probe started

08:18:20: TTY3: autoconfigure probe started

08:18:24: TTY1: autoconfigure probe started

08:18:25: TTY8: autoconfigure probe started

08:18:33: TTY4: autoconfigure probe started

08:18:43: TTY2: autoconfigure probe started

08:18:43: TTY7: autoconfigure probe started

08:18:43: TTY6: autoconfigure probe started

08:18:46: TTY3: autoconfigure probe started

08:18:50: TTY1: autoconfigure probe started

08:18:51: TTY8: autoconfigure probe started

08:18:59: TTY4: autoconfigure probe started

08:19:09: TTY2: autoconfigure probe started

08:19:09: TTY7: autoconfigure probe started

08:19:09: TTY6: autoconfigure probe started

08:19:12: TTY5: DSR came up

08:19:12: tty5: Modem: IDLE->READY

08:19:12: TTY3: autoconfigure probe started

08:19:12: TTY5: EXEC creation

08:19:12: TTY5: set timer type 10, 30 seconds

08:19:14: TTY5: Autoselect(2) sample 7E

08:19:14: TTY5: Autoselect(2) sample 7EFF

08:19:14: TTY5: Autoselect(2) sample 7EFF7D

08:19:14: TTY5: Autoselect(2) sample 7EFF7D23

08:19:14: TTY5 Autoselect cmd: ppp negotiate

08:19:14: TTY5: EXEC creation

08:19:14: TTY5: create timer type 1, 600 seconds

08:19:14: TTY5: destroy timer type 1 (OK)

08:19:14: TTY5: destroy timer type 0

08:19:14: TTY5: create timer type 2, 1200 seconds

08:19:16: %LINK-3-UPDOWN: Interface Async5, changed state to up

08:19:16: As5 PPP: Treating connection as a dedicated line

08:19:16: As5 PPP: Phase is ESTABLISHING, Active Open

08:19:16: As5 LCP: O CONFREQ [Closed] id 190 len 25

08:19:16: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:19:16: As5 LCP: AuthProto CHAP (0x0305C22305)

08:19:16: As5 LCP: MagicNumber 0x521D996F (0x0506521D996F)

08:19:16: As5 LCP: PFC (0x0702)

08:19:16: As5 LCP: ACFC (0x0802)

08:19:16: TTY1: autoconfigure probe started

08:19:16: TTY8: autoconfigure probe started

08:19:16: As5 LCP: I CONFACK [REQsent] id 190 len 25

08:19:16: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:19:16: As5 LCP: AuthProto CHAP (0x0305C22305)

08:19:16: As5 LCP: MagicNumber 0x521D996F (0x0506521D996F)

08:19:16: As5 LCP: PFC (0x0702)

08:19:16: As5 LCP: ACFC (0x0802)

08:19:17: As5 LCP: I CONFREQ [ACKrcvd] id 2 len 50

08:19:17: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:19:17: As5 LCP: MagicNumber 0x1A0C6630 (0x05061A0C6630)

08:19:17: As5 LCP: PFC (0x0702)

08:19:17: As5 LCP: ACFC (0x0802)

08:19:17: As5 LCP: Callback 6 (0x0D0306)

08:19:17: As5 LCP: MRRU 1614 (0x1104064E)

08:19:17: As5 LCP: EndpointDisc 1 Local

08:19:17: As5 LCP: (0x1317015DF477464F9E43ADB6C56CCEA3)

08:19:17: As5 LCP: (0xE83D4900000000)

08:19:17: As5 LCP: O CONFREJ [ACKrcvd] id 2 len 31

08:19:17: As5 LCP: MRRU 1614 (0x1104064E)

08:19:17: As5 LCP: EndpointDisc 1 Local

08:19:17: As5 LCP: (0x1317015DF477464F9E43ADB6C56CCEA3)

08:19:17: As5 LCP: (0xE83D4900000000)

08:19:17: As5 LCP: I CONFREQ [ACKrcvd] id 3 len 23

08:19:17: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:19:17: As5 LCP: MagicNumber 0x1A0C6630 (0x05061A0C6630)

08:19:17: As5 LCP: PFC (0x0702)

08:19:17: As5 LCP: ACFC (0x0802)

08:19:17: As5 LCP: Callback 6 (0x0D0306)

08:19:17: As5 LCP: O CONFACK [ACKrcvd] id 3 len 23

08:19:17: As5 LCP: ACCM 0x00000000 (0x020600000000)

08:19:17: As5 LCP: MagicNumber 0x1A0C6630 (0x05061A0C6630)

08:19:17: As5 LCP: PFC (0x0702)

08:19:17: As5 LCP: ACFC (0x0802)

08:19:17: As5 LCP: Callback 6 (0x0D0306)

08:19:17: As5 LCP: State is Open

08:19:17: As5 PPP: Phase is AUTHENTICATING, by this end

08:19:17: As5 CHAP: O CHALLENGE id 36 len 27 from "AS2509"

08:19:17: As5 LCP: I IDENTIFY [Open] id 4 len 18 magic 0x1A0C6630 MSRASV5.00

08:19:17: As5 LCP: I IDENTIFY [Open] id 5 len 24 magic 0x1A0C6630 MSRAS-1-THINKPAD

08:19:17: As5 CHAP: I RESPONSE id 36 len 30 from "znoopydog"

08:19:17: As5 CHAP: O SUCCESS id 36 len 4

08:19:17: As5 MCB: User znoopydog Callback Number - Server 2390

08:19:17: Async5 PPP: O MCB Request(1) id 58 len 7

08:19:17: Async5 MCB: O 1 3A 0 7 3 3 0

08:19:17: As5 MCB: O Request Id 58 Callback Type Server-Num delay 0

08:19:17: As5 PPP: Phase is CBCP

08:19:17: Async5 PPP: I MCB Response(2) id 58 len 7

08:19:17: Async5 MCB: I 2 3A 0 7 3 3 C

08:19:17: As5 MCB: Received response

08:19:17: As5 MCB: Response CBK-Server-Num 3 3 12

08:19:17: Async5 PPP: O MCB Ack(3) id 59 len 7

08:19:17: Async5 MCB: O 3 3B 0 7 3 3 C

08:19:17: As5 MCB: O Ack Id 59 Callback Type Server-Num delay 12

08:19:17: As5 MCB: Negotiated MCB with peer

08:19:17: As5 LCP: I TERMREQ [Open] id 6 len 16 (0x1A0C6630003CCD7400000000)

08:19:17: As5 LCP: O TERMACK [Open] id 6 len 4

08:19:17: As5 MCB: Peer terminating the link

08:19:17: As5 PPP: Phase is TERMINATING

08:19:17: As5 MCB: Link terminated by peer, Callback Needed

08:19:17: As5 MCB: Initiate Callback for znoopydog at 2390 using Async

08:19:17: As5 MCB: Async-callback in progress

08:19:17: As5 AAA/ACCT: Using PPP accounting list ""

08:19:19: As5 LCP: TIMEout: State TERMsent

08:19:19: As5 LCP: State is Closed

08:19:19: As5 PPP: Phase is DOWN

08:19:19: TTY5: Async Int reset: Dropping DTR

08:19:19: As5 PPP: Phase is ESTABLISHING, Passive Open

08:19:19: As5 LCP: State is Listen

08:19:21: %LINK-5-CHANGED: Interface Async5, changed state to reset

08:19:21: As5 LCP: State is Closed

08:19:21: As5 PPP: Phase is DOWN

08:19:21: As5 IPCP: Remove route to 172.80.100.101

08:19:24: TTY4: autoconfigure probe started

08:19:26: %LINK-3-UPDOWN: Interface Async5, changed state to down

08:19:26: As5 LCP: State is Closed

08:19:26: As5 PPP: Phase is DOWN

08:19:34: TTY2: autoconfigure probe started

08:19:34: TTY7: autoconfigure probe started

08:19:34: TTY6: autoconfigure probe started

08:19:34: CHAT5: Asserting DTR

08:19:35: CHAT5: Asserting DTR

08:19:37: TTY3: autoconfigure probe started

08:19:41: TTY1: autoconfigure probe started

08:19:41: TTY8: autoconfigure probe started

08:19:49: TTY4: autoconfigure probe started

08:19:57: TTY5: destroy timer type 1

08:19:57: TTY5: destroy timer type 0

08:19:57: TTY5: create timer type 2, 1200 seconds

08:19:57: TTY5: timer_create_bg error

08:19:59: %LINK-3-UPDOWN: Interface Async5, changed state to up

08:19:59: As5 PPP: Treating connection as a dedicated line

08:19:59: As5 PPP: Phase is ESTABLISHING, Active Open

08:19:59: As5 LCP: O CONFREQ [Closed] id 191 len 25

08:19:59: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:19:59: As5 LCP: AuthProto CHAP (0x0305C22305)

08:19:59: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:19:59: As5 LCP: PFC (0x0702)

08:19:59: As5 LCP: ACFC (0x0802)

08:19:59: TTY7: autoconfigure probe started

08:19:59: TTY2: autoconfigure probe started

08:19:59: TTY6: autoconfigure probe started

08:20:01: As5 LCP: TIMEout: State REQsent

08:20:01: As5 LCP: O CONFREQ [REQsent] id 192 len 25

08:20:01: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:01: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:01: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:01: As5 LCP: PFC (0x0702)

08:20:01: As5 LCP: ACFC (0x0802)

08:20:02: TTY3: autoconfigure probe started

08:20:03: As5 LCP: TIMEout: State REQsent

08:20:03: As5 LCP: O CONFREQ [REQsent] id 193 len 25

08:20:03: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:03: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:03: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:03: As5 LCP: PFC (0x0702)

08:20:03: As5 LCP: ACFC (0x0802)

08:20:05: As5 LCP: TIMEout: State REQsent

08:20:05: As5 LCP: O CONFREQ [REQsent] id 194 len 25

08:20:05: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:05: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:05: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:05: As5 LCP: PFC (0x0702)

08:20:05: As5 LCP: ACFC (0x0802)

08:20:06: TTY1: autoconfigure probe started

08:20:06: TTY8: autoconfigure probe started

08:20:07: As5 LCP: TIMEout: State REQsent

08:20:07: As5 LCP: O CONFREQ [REQsent] id 195 len 25

08:20:07: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:07: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:07: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:07: As5 LCP: PFC (0x0702)

08:20:07: As5 LCP: ACFC (0x0802)

08:20:09: As5 LCP: TIMEout: State REQsent

08:20:09: As5 LCP: O CONFREQ [REQsent] id 196 len 25

08:20:09: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:09: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:09: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:09: As5 LCP: PFC (0x0702)

08:20:09: As5 LCP: ACFC (0x0802)

08:20:11: As5 LCP: TIMEout: State REQsent

08:20:11: As5 LCP: O CONFREQ [REQsent] id 197 len 25

08:20:11: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:11: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:11: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:11: As5 LCP: PFC (0x0702)

08:20:11: As5 LCP: ACFC (0x0802)

08:20:13: As5 LCP: TIMEout: State REQsent

08:20:13: As5 LCP: O CONFREQ [REQsent] id 198 len 25

08:20:13: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:13: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:13: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:13: As5 LCP: PFC (0x0702)

08:20:13: As5 LCP: ACFC (0x0802)

08:20:14: TTY4: autoconfigure probe started

08:20:15: As5 LCP: TIMEout: State REQsent

08:20:15: As5 LCP: O CONFREQ [REQsent] id 199 len 25

08:20:15: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:15: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:15: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:15: As5 LCP: PFC (0x0702)

08:20:15: As5 LCP: ACFC (0x0802)

08:20:17: As5 LCP: TIMEout: State REQsent

08:20:17: As5 LCP: O CONFREQ [REQsent] id 200 len 25

08:20:17: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:17: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:17: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:17: As5 LCP: PFC (0x0702)

08:20:17: As5 LCP: ACFC (0x0802)

08:20:19: As5 LCP: TIMEout: State REQsent

08:20:19: As5 LCP: O CONFREQ [REQsent] id 201 len 25

08:20:19: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:19: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:19: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:19: As5 LCP: PFC (0x0702)

08:20:19: As5 LCP: ACFC (0x0802)

08:20:21: As5 LCP: TIMEout: State REQsent

08:20:21: TTY5: Async Int reset: Dropping DTR

08:20:21: As5 LCP: State is Listen

08:20:22: TTY5: DSR was dropped

08:20:22: tty5: Modem: READY->HANGUP

08:20:23: TTY5: dropping DTR, hanging up

08:20:23: tty5: Modem: HANGUP->IDLE

08:20:23: %LINK-5-CHANGED: Interface Async5, changed state to reset

08:20:23: As5 LCP: State is Closed

08:20:23: As5 PPP: Phase is DOWN

08:20:24: TTY5: cleanup pending. Delaying DTR

08:20:25: TTY5: cleanup pending. Delaying DTR

08:20:25: TTY2: autoconfigure probe started

08:20:25: TTY7: autoconfigure probe started

08:20:25: TTY6: autoconfigure probe started

08:20:26: TTY5: cleanup pending. Delaying DTR

08:20:26: TTY5: destroy timer type 0

08:20:26: TTY5: destroy timer type 1

08:20:26: TTY5: destroy timer type 3

08:20:26: TTY5: destroy timer type 4

08:20:26: TTY5: destroy timer type 2 (OK)

08:20:26: Async5: allowing modem_process to continue hangup

08:20:27: TTY5: restoring DTR

08:20:28: TTY5: autoconfigure probe started

08:20:28: TTY3: autoconfigure probe started

08:20:28: %LINK-3-UPDOWN: Interface Async5, changed state to down

08:20:28: As5 LCP: State is Closed

08:20:28: As5 PPP: Phase is DOWN

Thank You

[tepatel]

As you can see that the debug

08:20:19: As5 LCP: O CONFREQ [REQsent] id 201 len 25

08:20:19: As5 LCP: ACCM 0x000A0000 (0x0206000A0000)

08:20:19: As5 LCP: AuthProto CHAP (0x0305C22305)

08:20:19: As5 LCP: MagicNumber 0x521E421A (0x0506521E421A)

08:20:19: As5 LCP: PFC (0x0702)

08:20:19: As5 LCP: ACFC (0x0802)

08:20:21: As5 LCP: TIMEout: State REQsent

Where interface async 5 (tty5) is keeps on sending outbound LCP packets which are not replied by user (windows pc) so do you see the tx and rx led's on cleint modem flashing during that time?

Or do you see any incomfing packet errors on interface async 5?

For that you need to have "sh interface async x" where x is the modem number involved in that connection. So capture before and after callback connection and see the difference in interface statistics.

Try to use "Async mode dedicated" instead of "interactive" under the async interface

[jpcastro]

I've tried the async mode dedicated but doesn't work. As you can see I'm using user znoopydog to callback, this isn't a windows user.

Do I need to create this user in windows?

[tepatel]

Not sure how user znoopydog works regarding callback..but bottom line is the router's LCP Outbound packets are not replied by user..so after lots of retries, router giveup on that and disconnect the line..

So talk to those concern guys for that..Windows works great for callback.