Document ID: 6367
Contents
Introduction
Prerequisites
Requirements
Components Used
Conventions
Configure
Network Diagram
Configurations
Verify
Troubleshoot
Troubleshooting Commands (Optional)
NetPro Discussion Forums - Featured Conversations
Related Information
Introduction
This document provides a sample configuration for an Async device requesting PPP callback in a Virtual Private Dialup Network (VPDN) setup.
Note: The L2TP Network Server (LNS) closes the VPDN session in order to make the callback.
Prerequisites
Requirements
There are no specific requirements for this document.
Components Used
The information in this document is based on these software and hardware versions:
-
The L2TP Access Concentrator (LAC), which is an AS5300 running Cisco IOSĀ® Software Release 12.1(6).
-
The LNS, which is a Cisco 7200 router running Cisco IOS Software Release 12.1(6).
The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, make sure that you understand the potential impact of any command.
Conventions
For more information on document conventions, refer to Cisco Technical Tips Conventions.
Configure
In this section, you are presented with the information to configure the features described in this document.
Note: To find additional information on the commands used in this document, use the Command Lookup Tool ( registered customers only) .
Network Diagram
This document uses this network setup:
Configurations
This document uses these configurations:
-
LAC
Note: Remember these points about the LAC:
-
This clones the async incoming call from the rotary dialer used for vpdn dial-out. On the group-async interface, this is:
dialer rotary-group 10
-
The ppp callback accept command is only specified on the dialer interface.
-
Make sure you define the callback script and apply it on the lines using the script callback command.
-
-
LNS
Note: Remember these points about the LNS:
-
The callback-dialerstring command is required when defining the username.
-
It is possible to either negotiate the callback number or to define it using the username <username> command.
-
The ppp callback accept command is only required on a dialer-profile interface.
-
|
LAC |
|---|
hostname monica ! aaa new-model aaa authentication ppp default local aaa authorization network default local ! username main-lac password 0 <password> username main-lns password 0 <password> spe 1/0 1/9 firmware location pw 2722.ios ! vpdn enable no vpdn logging ! vpdn-group main request-dialin protocol l2tp domain cb.com accept-dialout protocol l2tp dialer 10 terminate-from hostname main-lns initiate-to ip 10.200.20.14 local name main-lac ! isdn switch-type primary-net5 chat-script dial ABORT ERROR ABORT BUSY ABORT "NO ANSWER" "" "ATZ" OK "ATDT\T" TIMEOUT 90 CONNECT \c ! controller E1 0 clock source line primary pri-group timeslots 1-31 ! ! interface Loopback0 ip address 1.1.1.1 255.255.255.0 ! interface Ethernet0 ip address 10.200.20.28 255.255.255.0 no ip redirects standby ip 10.200.20.201 ! interface Serial0:15 no ip address encapsulation ppp dialer rotary-group 10 isdn switch-type primary-net5 isdn incoming-voice modem no cdp enable ppp authentication chap ! ! interface Group-Async1 ip unnumbered Ethernet0 dialer in-band dialer rotary-group 10 async mode interactive peer default ip address pool local ppp authentication chap group-range 3 60 ! interface Dialer10 ip unnumbered Ethernet0 encapsulation ppp dialer in-band dialer aaa dialer-group 1 no cdp enable ppp callback accept ppp authentication chap ! ip local pool local 10.200.20.246 10.200.20.254 ! line 3 60 no exec autoselect ppp script callback dial modem answer-timeout 0 modem InOut modem autoconfigure type mica transport output lat pad telnet rlogin udptn v120 lapb-ta escape-character NONE telnet transparent flowcontrol NONE |
|
LNS |
|---|
hostname fifi username main-lns password 0 <password> username main-lac password 0 <password> username Async@cb.com callback-dialstring 6015 password 0 <password> ! vpdn enable no vpdn logging ! vpdn-group main accept-dialin protocol l2tp virtual-template 20 request-dialout protocol l2tp pool-member 10 terminate-from hostname main-lac initiate-to ip 10.200.20.28 local name main-lns ! controller E1 3/0 shutdown framing NO-CRC4 clock source internal linecode ami ! interface Loopback20 ip address 1.1.1.1 255.255.255.255 ! interface Ethernet1/0 ip address 10.200.20.14 255.255.255.0 ! interface Virtual-Template20 ip unnumbered Loopback20 peer default ip address pool pptp ppp authentication chap ! interface Dialer1 ip unnumbered Loopback20 encapsulation ppp dialer pool 10 dialer remote-name Async@cb.com dialer wait-for-carrier-time 45 dialer string 6116 class cb dialer vpdn dialer-group 1 peer default ip address pool pptp ppp callback accept ! ppp authentication chap ! ip local pool pptp 1.100.0.1 1.100.0.10 ip classless ! map-class dialer cb dialer callback-server username dialer-list 1 protocol ip permit |
Verify
This section provides information you can use to confirm your configuration is working properly.
Certain show commands are supported by the Output Interpreter Tool ( registered customers only) , which allows you to view an analysis of show command output.
-
show vpdn—displays information about active Level 2 Forwarding (L2F) protocol tunnel and message identifiers in a VPDN.
-
show vpdn session all—displays summary information about all active L2F and L2TP tunnels.
-
show caller—displays caller information.
-
show caller user <username@domain>—displays a summary of caller information for the username you provide.
Here is the output of these show commands:
monica#show vpdn L2TP Tunnel and Session Information Total tunnels 1 sessions 1 LocID RemID Remote Name State Remote Address Port Sessions 41066 7118 main-lns est 10.200.20.14 1701 1 LocID RemID TunID Intf Username State Last Chg Fastswitch28 24 41066 As60 est 00:00:20 enabled % No active L2F tunnels monica#show line 60 Tty Typ Tx/Rx A Modem Roty AccO AccI Uses Noise Overruns Int A 60 TTY - inout - - - 0 0 0/0 - Ready Line 60, Location: "", Type: "" Length: 24 lines, Width: 80 columns Status: Ready, Active, No Exit Banner, Async Interface Active HW PPP Support Active, Modem Detected, CTS Raised Capabilities: EXEC Suppressed, Telnet Transparent Mode, Modem Callout Modem RI is CD, Line usable as async interface, Modem Autoconfigure Integrated Modem Linenumber Not Suppressed Modem state: Ready modem(slot/port)=1/59, state=CONNECTED dsx1(slot/unit/channel)=0/0/30, status=VDEV_STATUS_ACTIVE_CALL. Modem hardware state: CTS DSR DTR RTS Group codes: 0Line is running PPP. 0 output packets queued, 1 input packets. Async Escape map is 00000000000000000101000000000000, Modem Configured Special Chars: Escape Hold Stop Start Disconnect Activation none none - - none Timeouts: Idle EXEC Idle Session Modem Answer Session Dispatch 00:10:00 never none not set Idle Session Disconnect Warning never Login-sequence User Response 00:00:30 Autoselect Initial Wait not set Modem type is mica. Session limit is not set. Time since activation: never Editing is enabled. History is enabled, history size is 10. DNS resolution in show commands is enabled Full user help is disabled Allowed input transports are none. Allowed output transports are lat pad telnet rlogin udptn v120 lapb-ta. Preferred transport is lat. No output characters are padded No special data dispatching characters
fifi#show vpdn L2TP Tunnel and Session Information Total tunnels 1 sessions 1 LocID RemID Remote Name State Remote Address Port Sessions 47336 12644 main-lac est 10.200.20.28 1701 1 LocID RemID TunID Intf Username State Last Chg Fastswitch 22 26 47336 Vi1 Async@cb.com est 00:00:24 enabled % No active L2F tunnels fifi#show vpdn session all L2TP Session Information Total tunnels 1 sessions 1 Call id 22 is up on tunnel id 47336 Remote tunnel name is main-lacInternet Address is 10.200.20.28 Session username is Async@cb.com, state is established Time since change 00:00:30, interface Vi1 Remote call id is 26 Fastswitching is enabled 13 packets sent, 33 received 359 bytes sent, 2109 received Sequencing is off % No active L2F tunnels fifi#show caller Active Idle Line User Service Time Time con 0 - TTY 1d13h 00:00:00 Vi1 Async@cb.com PPP L2TP 00:00:32 00:00:36 fifi#show caller user Async@cb.com detailed User: Async@cb.com, line Vi1, service PPP L2TP Active time 00:00:44, Idle time 00:00:48 Timeouts: Absolute Idle Limits: - 00:02:00 Disconnect in: - 00:01:11 PPP: LCP Open, CHAP (<- local), IPCP LCP: -> peer, ACCM, AuthProto, MagicNumber, PCompression, ACCompression <- peer, ACCM, MagicNumber, PCompression, ACCompression NCP: Listen CDPCP NCP: Open IPCP IPCP: <- peer, Address -> peer, Address Dialer: Connected to 6015, outbound Idle timer 120 secs, idle 48 secs Type is DIALER VPDN, group Di1 Cause: Callback return call IP: Local 1.1.1.1, remote 1.100.0.1 VPDN: NAS main-lac, MID 22, MID Unknown HGW main-lns, NAS CLID 0, HGW CLID 0, tunnel open Counts: 53 packets input, 4632 bytes, 0 no buffer 0 input errors, 0 CRC, 0 frame, 0 overrun 15 packets output, 287 bytes, 0 underruns 0 output errors, 0 collisions, 0 interface resets
Troubleshoot
This section provides information you can use to troubleshoot your configuration.
Troubleshooting Commands (Optional)
Note: Before issuing debug commands, refer to Important Information on Debug Commands.
-
debug aaa authorization—displays information on AAA/TACACS+ authorization.
-
debug dialer—displays debugging information about the packets received on a dialer interface.
-
debug l2x-events—displays messages about events that are part of normal PPP tunnel establishment or shutdown for L2.
-
debug ppp negotiation—causes the debug ppp command to display PPP packets transmitted during PPP startup, where PPP options are negotiated.
-
debug ppp authentication—causes the debug ppp command to display authentication protocol messages, including Challenge Authentication Protocol (CHAP) packet exchanges, and Password Authentication Protocol (PAP) exchanges.
-
debug isdn q931—displays information about call setup and teardown of ISDN network connections (Layer 3) between the local router (user side), and the network.
-
debug modem—displays modem line activity on an access server.
-
debug modem csm—debugs the Call Switching Module (CSM) that is used to connect calls on the modem.
-
debug vpdn events—displays messages about events that are part of normal tunnel establishment or shutdown.
-
debug vtemplate—displays cloning information for a virtual access interface from the time it is cloned from a virtual template to the time the virtual access interface comes down when the call ends.
-
debug callback—displays callback events when the router is using a modem, and a chat script to call back on a terminal line.
Here is the output of these debug commands:
Incoming call on LAC from async device requesting MS-callback:
Jun 18 05:38:26.236: ISDN Se0:15: RX <- SETUP pd = 8 callref = 0x28E7 Jun 18 05:38:26.236: Sending Complete Jun 18 05:38:26.236: Bearer Capability i = 0x9090A3 Jun 18 05:38:26.236: Channel ID i = 0xA1839F Jun 18 05:38:26.236: Progress Ind i = 0x8183 - Origination address is non-ISDN Jun 18 05:38:26.240: Calling Party Number i = 0xA1, '6015', Plan:ISDN, Type:National Jun 18 05:38:26.240: Called Party Number i = 0x81, '211', Plan:ISDN, Type:Unknown Jun 18 05:38:26.240: Locking Shift to Codeset 6 Jun 18 05:38:26.240: Codeset 6 IE 0x28 i = 'Analog', 0x20, '15' Jun 18 05:38:26.240: VDEV_ALLOCATE: 1/10 is allocated Jun 18 05:38:26.244: ISDN Se0:15: TX -> CALL_PROC pd = 8 callref = 0xA8E7 Jun 18 05:38:26.244: Channel ID i = 0xA9839F Jun 18 05:38:26.244: EVENT_FROM_ISDN::dchan_idb=0x61C99E70, call_id=0xC7, ces=0x1 bchan=0x1E, event=0x1, cause=0x0 Jun 18 05:38:26.244: EVENT_FROM_ISDN:(00C7): DEV_INCALL at slot 1 and port 10 Jun 18 05:38:26.244: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 1, port 10 Jun 18 05:38:26.244: Mica Modem(1/10): Configure(0x1 = 0x0) Jun 18 05:38:26.244: Mica Modem(1/10): Configure(0x23 = 0x0) Jun 18 05:38:26.244: Mica Modem(1/10): Call Setup Jun 18 05:38:26.244: Enter csm_connect_pri_vdev function Jun 18 05:38:26.244: csm_connect_pri_vdev:tdm_allocate_bp_ts() call. BP TS allocated at bp_stream0, bp_Ch12,vdev_common 0x616B8C58 Jun 18 05:38:26.244: ISDN Se0:15: TX -> ALERTING pd = 8 callref = 0xA8E7 Jun 18 05:38:26.404: Mica Modem(1/10): State Transition to Call Setup Jun 18 05:38:26.404: Mica Modem(1/10): Went offhook Jun 18 05:38:26.404: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 10 Jun 18 05:38:26.404: ISDN Se0:15: TX -> CONNECT pd = 8 callref = 0xA8E7 han 30, dsl 0 Jun 18 05:38:26.464: EVENT_FROM_ISDN::dchan_idb=0x61C99E70, call_id=0xC7, ces=0x1 bchan=0x1E, event=0x4, cause=0x0 Jun 18 05:38:26.464: EVENT_FROM_ISDN:(00C7): DEV_CONNECTED at slot 1 and port 10 Jun 18 05:38:26.468: CSM_PROC_IC6_WAIT_FOR_CONNECT: CSM_EVENT_ISDN_CONNECTED at slot 1, port 10 Jun 18 05:38:26.468: Mica Modem(1/10): Link Initiate Jun 18 05:38:26.468: %ISDN-6-CONNECT: Interface Serial0:30 is now connected to 6015 Jun 18 05:38:27.604: Mica Modem(1/10): State Transition to Connect Jun 18 05:38:32.048: Mica Modem(1/10): State Transition to Link Jun 18 05:38:43.456: Mica Modem(1/10): State Transition to Trainup Jun 18 05:38:47.480: Mica Modem(1/10): State Transition to EC Negotiating Jun 18 05:38:47.900: Mica Modem(1/10): State Transition to Steady State Jun 18 05:38:48.752: TTY11: DSR came up Jun 18 05:38:48.752: tty11: Modem: IDLE->(unknown) Jun 18 05:38:48.752: TTY11: Autoselect started Jun 18 05:38:48.752: TTY11: create timer type 0, 120 seconds Jun 18 05:38:51.004: TTY11: Autoselect sample 7E Jun 18 05:38:51.004: TTY11: Autoselect sample 7EFF Jun 18 05:38:51.004: TTY11: Autoselect sample 7EFF7D Jun 18 05:38:51.004: TTY11: Autoselect sample 7EFF7D23 Jun 18 05:38:51.004: TTY11 Autoselect cmd: ppp negotiate Jun 18 05:38:51.004: TTY11: destroy timer type 0 (OK) Jun 18 05:38:51.004: TTY11: EXEC creation Jun 18 05:38:51.004: TTY11: create timer type 1, 600 seconds Jun 18 05:38:51.008: TTY11: destroy timer type 1 (OK) Jun 18 05:38:51.008: TTY11: destroy timer type 0 Jun 18 05:38:51.008: As11 DDR: Dialer received incoming call from Jun 18 05:38:51.008: As11 PPP: Async Protocol Mode started for 10.200.20.251 Jun 18 05:38:51.008: As11 AAA/ACCT: Using PPP accounting list "" Jun 18 05:38:51.012: Di10 IPCP: Install route to 10.200.20.251 Jun 18 05:38:53.008: %LINK-3-UPDOWN: Interface Async11, changed state to up Jun 18 05:38:53.008: As11 DDR: Dialer statechange to up Jun 18 05:38:53.008: As11 DDR: Dialer received incoming call from Jun 18 05:38:53.008: As11 PPP: Treating connection as a callin Jun 18 05:38:53.008: As11 PPP: Phase is ESTABLISHING, Passive Open Jun 18 05:38:53.008: As11 LCP: State is Listen Jun 18 05:38:54.000: As11 LCP: I CONFREQ [Listen] id 3 len 23 Jun 18 05:38:54.000: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:54.000: As11 LCP: MagicNumber 0x1EF15DEC (0x05061EF15DEC) Jun 18 05:38:54.000: As11 LCP: PFC (0x0702) Jun 18 05:38:54.000: As11 LCP: ACFC (0x0802) Jun 18 05:38:54.000: As11 LCP: Callback 6 (0x0D0306) Jun 18 05:38:54.000: Unthrottle 11 Jun 18 05:38:54.000: As11 LCP: O CONFREQ [Listen] id 1 len 25 Jun 18 05:38:54.000: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:54.000: As11 LCP: AuthProto CHAP (0x0305C22305) Jun 18 05:38:54.000: As11 LCP: MagicNumber 0x29626BEB (0x050629626BEB) Jun 18 05:38:54.000: As11 LCP: PFC (0x0702) Jun 18 05:38:54.000: As11 LCP: ACFC (0x0802) Jun 18 05:38:54.000: As11 LCP: O CONFACK [Listen] id 3 len 23 Jun 18 05:38:54.000: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:54.000: As11 LCP: MagicNumber 0x1EF15DEC (0x05061EF15DEC) Jun 18 05:38:54.000: As11 LCP: PFC (0x0702) Jun 18 05:38:54.000: As11 LCP: ACFC (0x0802) Jun 18 05:38:54.000: As11 LCP: Callback 6 (0x0D0306) Jun 18 05:38:56.000: As11 LCP: TIMEout: State ACKsent Jun 18 05:38:56.000: As11 LCP: O CONFREQ [ACKsent] id 2 len 25 Jun 18 05:38:56.000: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:56.000: As11 LCP: AuthProto CHAP (0x0305C22305) Jun 18 05:38:56.000: As11 LCP: MagicNumber 0x29626BEB (0x050629626BEB) Jun 18 05:38:56.000: As11 LCP: PFC (0x0702) Jun 18 05:38:56.000: As11 LCP: ACFC (0x0802) Jun 18 05:38:57.012: As11 LCP: I CONFREQ [ACKsent] id 4 len 23 Jun 18 05:38:57.012: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:57.012: As11 LCP: MagicNumber 0x1EF15DEC (0x05061EF15DEC) Jun 18 05:38:57.012: As11 LCP: PFC (0x0702) Jun 18 05:38:57.012: As11 LCP: ACFC (0x0802) Jun 18 05:38:57.012: As11 LCP: Callback 6 (0x0D0306) Jun 18 05:38:57.012: As11 LCP: O CONFACK [ACKsent] id 4 len 23 Jun 18 05:38:57.012: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:57.012: As11 LCP: MagicNumber 0x1EF15DEC (0x05061EF15DEC) Jun 18 05:38:57.012: As11 LCP: PFC (0x0702) Jun 18 05:38:57.012: As11 LCP: ACFC (0x0802) Jun 18 05:38:57.012: As11 LCP: Callback 6 (0x0D0306) Jun 18 05:38:58.000: As11 LCP: TIMEout: State ACKsent Jun 18 05:38:58.000: As11 LCP: O CONFREQ [ACKsent] id 3 len 25 Jun 18 05:38:58.000: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:58.000: As11 LCP: AuthProto CHAP (0x0305C22305) Jun 18 05:38:58.000: As11 LCP: MagicNumber 0x29626BEB (0x050629626BEB) Jun 18 05:38:58.000: As11 LCP: PFC (0x0702) Jun 18 05:38:58.000: As11 LCP: ACFC (0x0802) Jun 18 05:38:58.100: As11 LCP: I CONFACK [ACKsent] id 3 len 25 Jun 18 05:38:58.100: As11 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:38:58.100: As11 LCP: AuthProto CHAP (0x0305C22305) Jun 18 05:38:58.100: As11 LCP: MagicNumber 0x29626BEB (0x050629626BEB) Jun 18 05:38:58.100: As11 LCP: PFC (0x0702) Jun 18 05:38:58.100: As11 LCP: ACFC (0x0802) Jun 18 05:38:58.100: As11 LCP: State is Open Jun 18 05:38:58.100: As11 PPP: Phase is AUTHENTICATING, by this end Jun 18 05:38:58.100: As11 CHAP: O CHALLENGE id 1 len 27 from "monica" Jun 18 05:38:58.212: As11 CHAP: I RESPONSE id 1 len 34 from "Async@cb.com" Jun 18 05:38:58.212: As11 PPP: Phase is FORWARDING Jun 18 05:38:58.212: As11 VPDN: Got DNIS string 211 Jun 18 05:38:58.212: As11 VPDN: Looking for tunnel -- dnis:211 -- Jun 18 05:38:58.212: AAA: parse name=Async11 idb type=10 tty=11 Jun 18 05:38:58.212: AAA: name=Async11 flags=0x11 type=4 shelf=0 slot=0 adapter=0 port=11 channel=0 Jun 18 05:38:58.212: AAA: parse name=Serial0:30 idb type=13 tty=-1 Jun 18 05:38:58.212: AAA: name=Serial0:30 flags=0x51 type=1 shelf=0 slot=0 adapter=0 port=0 channel=30 Jun 18 05:38:58.212: AAA/MEMORY: create_user (0x61C522B8) user='dnis:211' ruser='' port='Async11' rem_addr='6015/211' authen_type=NONE service=LOGIN priv=0 Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): Port='Async11' list='default' service=NET Jun 18 05:38:58.212: AAA/AUTHOR/VPDN: Async11 (857164279) user='dnis:211' Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): send AV service=ppp Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): send AV protocol=vpdn Jun 18 05:38:58.212: AAA/AUTHOR/VPDN (857164279) no method list defined Type "network" list "default". Using method "local" Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): Method=LOCAL Jun 18 05:38:58.212: AAA/AUTHOR/VPDN/LOCAL: Looking for tunnel dnis:211 Jun 18 05:38:58.212: AAA/AUTHOR/VPDN/LOCAL: tunnel dnis:211 doesn't exist Jun 18 05:38:58.212: AAA/AUTHOR (857164279): Post authorization status = ERROR Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): Method=NOT_SET Jun 18 05:38:58.212: Async11 AAA/AUTHOR/VPDN (857164279): no methods left to try Jun 18 05:38:58.216: AAA/AUTHOR (857164279): Post authorization status = ERROR Jun 18 05:38:58.216: VPDN/dnis:211: Authorization failed, could not talk to AAA server or local tunnel problem Jun 18 05:38:58.216: AAA/MEMORY: free_user (0x61C522B8) user='dnis:211' ruser='' port='Async11' rem_addr='6015/211' authen_type=NONE service=LOGIN priv=0 Jun 18 05:38:58.216: As11 VPDN: Looking for tunnel -- cb.com -- Jun 18 05:38:58.216: AAA: parse name=Async11 idb type=10 tty=11 Jun 18 05:38:58.216: AAA: name=Async11 flags=0x11 type=4 shelf=0 slot=0 adapter=0 port=11 channel=0 Jun 18 05:38:58.216: AAA: parse name=Serial0:30 idb type=13 tty=-1 Jun 18 05:38:58.216: AAA: name=Serial0:30 flags=0x51 type=1 shelf=0 slot=0 adapter=0 port=0 channel=30 Jun 18 05:38:58.216: AAA/MEMORY: create_user (0x61C522B8) user='cb.com' ruser='' port='Async11' rem_addr='6015/211' authen_type=NONE service=LOGIN priv=0 Jun 18 05:38:58.216: Async11 AAA/AUTHOR/VPDN (1721745696): Port='Async11' list='default' service=NET Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Async11 (1721745696) user='cb.com' Jun 18 05:38:58.216: Async11 AAA/AUTHOR/VPDN (1721745696): send AV service=ppp Jun 18 05:38:58.216: Async11 AAA/AUTHOR/VPDN (1721745696): send AV protocol=vpdn Jun 18 05:38:58.216: AAA/AUTHOR/VPDN (1721745696) no method list defined Type "network" list "default". Using method "local" Jun 18 05:38:58.216: Async11 AAA/AUTHOR/VPDN (1721745696): Method=LOCAL Jun 18 05:38:58.216: AAA/AUTHOR/VPDN/LOCAL: Looking for tunnel cb.com Jun 18 05:38:58.216: AAA/AUTHOR/VPDN/LOCAL: LNS is 10.200.20.14 Jun 18 05:38:58.216: AAA/AUTHOR (1721745696): Post authorization status = PASS_ADD Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV service=ppp Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV protocol=vpdn Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV tunnel-type*l2tp Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV tunnel-id=main-lac Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV ip-addresses=10.200.20.14 Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV vpdn-group*main Jun 18 05:38:58.216: AAA/AUTHOR/VPDN: Processing AV server-name*main-lac Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV l2tp-busy-disconnect*yes Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV dout-type*2 Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV dout-dialer*10 Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV l2tp-cm-min-timeout*1 Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV l2tp-cm-max-timeout*8 Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV l2tp-cm-retransmit-retries*15 Jun 18 05:38:58.220: AAA/AUTHOR/VPDN: Processing AV l2tp-tunnel-timeout-setup*300 Jun 18 05:38:58.220: As11 VPDN/main-lac/main: Got tunnel info for cb.com Jun 18 05:38:58.220: As11 VPDN/main-lac/main: LAC main-lac Jun 18 05:38:58.220: As11 VPDN/main-lac/main: l2tp-busy-disconnect yes Jun 18 05:38:58.220: As11 VPDN/main-lac/main: IP 10.200.20.14 Jun 18 05:38:58.220: AAA/MEMORY: free_user (0x61C522B8) user='cb.com' ruser='' port='Async11' rem_addr='6015/211' authen_type=NONE service=LOGIN priv=0 Jun 18 05:38:58.220: As11 VPDN/main: curlvl 1 Address 0: 10.200.20.14, priority 1 Jun 18 05:38:58.220: As11 VPDN/main: Select non-active address 10.200.20.14, priority 1 Jun 18 05:38:58.220: As11 VPDN: Find LNS process created Jun 18 05:38:58.220: Tnl 26855 L2TP: SM State idle Jun 18 05:38:58.220: Tnl 26855 L2TP: O SCCRQ Jun 18 05:38:58.220: Tnl 26855 L2TP: Tunnel state change from idle to wait-ctl-reply Jun 18 05:38:58.220: Tnl 26855 L2TP: SM State wait-ctl-reply Jun 18 05:38:58.224: As11 VPDN: Forward to address 10.200.20.14 Jun 18 05:38:58.224: As11 VPDN: Pending Jun 18 05:38:58.224: As11 VPDN: Process created Jun 18 05:38:58.224: Tnl 26855 L2TP: I SCCRP from main-lns Jun 18 05:38:58.224: Tnl 26855 L2TP: Got a challenge from remote peer, main-lns Jun 18 05:38:58.224: Tnl 26855 L2TP: Got a response from remote peer, main-lns Jun 18 05:38:58.224: Tnl 26855 L2TP: Tunnel Authentication success Jun 18 05:38:58.224: Tnl 26855 L2TP: Tunnel state change from wait-ctl-reply to established Jun 18 05:38:58.228: Tnl 26855 L2TP: O SCCCN to main-lns tnlid 59995 Jun 18 05:38:58.228: Tnl 26855 L2TP: SM State established Jun 18 05:38:58.228: As11 VPDN: Forwarding... Jun 18 05:38:58.228: As11 DDR: Authenticated host Async@cb.com with no matching dialer map Jun 18 05:38:58.228: As11 VPDN: Bind interface direction=1 Jun 18 05:38:58.228: Tnl/Cl 26855/27 L2TP: Session FS enabled Jun 18 05:38:58.228: Tnl/Cl 26855/27 L2TP: Session state change from idle to wait-for-tunnel Jun 18 05:38:58.228: As11 Tnl/Cl 26855/27 L2TP: Create session Jun 18 05:38:58.228: Tnl 26855 L2TP: SM State established Jun 18 05:38:58.228: As11 Tnl/Cl 26855/27 L2TP: O ICRQ to main-lns 59995/0 Jun 18 05:38:58.228: As11 Tnl/Cl 26855/27 L2TP: Session state change from wait-for-tunnel to wait-reply Jun 18 05:38:58.228: As11 VPDN: Async@cb.com is forwarded Jun 18 05:38:58.232: Di10 IPCP: Remove route to 10.200.20.251 Jun 18 05:38:58.232: As11 Tnl/Cl 26855/27 L2TP: O ICCN to main-lns 59995/23 Jun 18 05:38:58.232: As11 Tnl/Cl 26855/27 L2TP: Session state change from wait-reply to established Jun 18 05:38:59.228: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async11, changed state to up Jun 18 05:39:08.797: Mica Modem(1/10): State Transition to Steady State Speedshifting Jun 18 05:39:10.057: Mica Modem(1/10): State Transition to Steady State Session closed due to callback : Jun 18 05:39:20.629: Mica Modem(1/10): State Transition to Terminating Jun 18 05:39:20.797: TTY11: DSR was dropped Jun 18 05:39:20.797: tty11: Modem: READY->(unknown) Jun 18 05:39:21.229: Mica Modem(1/10): State Transition to Idle Jun 18 05:39:21.229: Mica Modem(1/10): Went onhook Jun 18 05:39:21.229: CSM_PROC_IC7_OC6_CONNECTED: CSM_EVENT_MODEM_ONHOOK at slot 1, port 10 Jun 18 05:39:21.229: Enter csm_enter_idle_state Jun 18 05:39:21.229: VDEV_DEALLOCATE: slot 1 and port 10 is deallocated Jun 18 05:39:21.229: %ISDN-6-DISCONNECT: Interface Serial0:30 disconnected from 6015 , call lasted 54 seconds Jun 18 05:39:21.233: ISDN Se0:15: TX -> DISCONNECT pd = 8 callref = 0xA8E7 Jun 18 05:39:21.233: Cause i = 0x8090 - Normal call clearing Jun 18 05:39:21.257: ISDN Se0:15: RX <- RELEASE pd = 8 callref = 0x28E7 Jun 18 05:39:21.261: ISDN Se0:15: TX -> RELEASE_COMP pd = 8 callref = 0xA8E7 Jun 18 05:39:21.261: %LINK-3-UPDOWN: Interface Serial0:30, changed state to down Jun 18 05:39:21.261: Se0:30 LCP: State is Closed Jun 18 05:39:21.261: Se0:30 DDR: disconnecting call Jun 18 05:39:21.797: TTY11: dropping DTR, hanging up Jun 18 05:39:21.797: TTY11: Async Int reset: Dropping DTR Jun 18 05:39:21.797: tty11: Modem: HANGUP->(unknown) Jun 18 05:39:21.797: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:21.829: Mica Modem(1/10): State Transition to Terminating Jun 18 05:39:21.889: Mica Modem(1/10): State Transition to Idle Jun 18 05:39:22.441: As11 Tnl/Cl 26855/27 L2TP: I CDN from main-lns tnl 59995, cl 23 Jun 18 05:39:22.441: As11 Tnl/Cl 26855/27 L2TP: Destroying session Jun 18 05:39:22.441: As11 Tnl/Cl 26855/27 L2TP: Session state change from established to idle Jun 18 05:39:22.445: As11 Tnl/Cl 26855/27 L2TP: VPDN: Releasing idb for LAC/LNS tunnel 26855/59995 session 27 state idle Jun 18 05:39:22.445: Tnl 26855 L2TP: Tunnel state change from established to no-sessions-left Jun 18 05:39:22.445: Tnl 26855 L2TP: No more sessions in tunnel, shutdown (likely) in 15 seconds Jun 18 05:39:22.801: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:22.801: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:23.797: %LINK-3-UPDOWN: Interface Async11, changed state to down Jun 18 05:39:23.797: As11 VPDN: Reset Jun 18 05:39:23.797: As11 PPP: Phase is TERMINATING Jun 18 05:39:23.797: As11 LCP: State is Closed Jun 18 05:39:23.797: As11 PPP: Phase is DOWN Jun 18 05:39:23.797: As11 VPDN: Cleanup Jun 18 05:39:23.797: As11 VPDN: Reset Jun 18 05:39:23.797: As11 VPDN: Unbind interface Jun 18 05:39:23.801: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:23.801: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:24.797: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async11, changed state to down Jun 18 05:39:24.805: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:24.805: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:25.805: TTY11: cleanup pending. Delaying DTR Jun 18 05:39:25.805: TTY11: cleanup pending. Delaying DTR monica# monica# Jun 18 05:39:26.797: Async11: Async protocol mode stopped for 0.0.0.0 Jun 18 05:39:26.797: Unthrottle 11 Jun 18 05:39:26.797: TTY11: destroy timer type 0 Jun 18 05:39:26.797: TTY11: destroy timer type 1 Jun 18 05:39:26.797: TTY11: destroy timer type 3 Jun 18 05:39:26.797: TTY11: destroy timer type 4 Jun 18 05:39:26.797: TTY11: destroy timer type 2 Jun 18 05:39:26.797: Async11: allowing modem_process to continue hangup Jun 18 05:39:26.805: TTY11: restoring DTR Jun 18 05:39:26.805: TTY11: autoconfigure probe started Jun 18 05:39:32.441: Tnl 26855 L2TP: I StopCCN from main-lns tnl 59995 Jun 18 05:39:32.441: Tnl 26855 L2TP: Shutdown tunnel Jun 18 05:39:32.441: Tnl 26855 L2TP: Tunnel state change from no-sessions-left to idle Session/Tunnel reopened for callback : Jun 18 05:39:37.445: L2TP: I SCCRQ from main-lns tnl 7118 Jun 18 05:39:37.445: Tnl 41066 L2TP: Got a challenge in SCCRQ, main-lns Jun 18 05:39:37.445: Tnl 41066 L2TP: New tunnel created for remote main-lns, address 10.200.20.14 Jun 18 05:39:37.445: Tnl 41066 L2TP: O SCCRP to main-lns tnlid 7118 Jun 18 05:39:37.445: Tnl 41066 L2TP: Tunnel state change from idle to wait-ctl-reply Jun 18 05:39:37.449: Tnl 41066 L2TP: I SCCCN from main-lns tnl 7118 Jun 18 05:39:37.449: Tnl 41066 L2TP: Got a Challenge Response in SCCCN from main-lns Jun 18 05:39:37.449: Tnl 41066 L2TP: Tunnel Authentication success Jun 18 05:39:37.449: Tnl 41066 L2TP: Tunnel state change from wait-ctl-reply to established Jun 18 05:39:37.449: Tnl 41066 L2TP: SM State established Jun 18 05:39:37.449: Tnl 41066 L2TP: I OCRQ from main-lns tnl 7118 Jun 18 05:39:37.449: Tnl/Cl 41066/28 L2TP: Session FS enabled Jun 18 05:39:37.449: Tnl/Cl 41066/28 L2TP: New session created Jun 18 05:39:37.453: 28A0: Same state, 0 Jun 18 05:39:37.453: DSES 28A0: Session create Jun 18 05:39:37.453: L2TP: Send OCRP Jun 18 05:39:37.453: Tnl/Cl 41066/28 L2TP: Session state change from idle to wait-cs-answer Jun 18 05:39:37.453: DSES 0x28A0: Building dialer map Jun 18 05:39:37.453: Dialout 0x28A0: Next hop name is 6015 Jun 18 05:39:37.453: As60 DDR: rotor dialout [priority] Jun 18 05:39:37.453: As60 DDR: Dialing cause dialer session 0x28A0 Jun 18 05:39:37.453: As60 DDR: Attempting to dial 6015 Jun 18 05:39:37.453: CHAT60: Attempting async line dialer script Jun 18 05:39:37.453: CHAT60: no matching chat script found for 6015 Jun 18 05:39:37.453: CHAT60: Dialing using Modem script: d0efault-d0ials0cript & System script: none Jun 18 05:39:37.453: CHAT60: process started Jun 18 05:39:37.453: CHAT60: Asserting DTR Jun 18 05:39:37.453: CHAT60: Chat script d0efault-d0ials0cript started Jun 18 05:39:37.625: Mica Modem(1/59): Rcvd Dial String(6015) Jun 18 05:39:37.625: CSM_PROC_IDLE: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 59 Jun 18 05:39:37.625: csm_get_signaling_channel dchan_index=24954,next_index=0 Jun 18 05:39:37.625: csm_get_signaling_channel dchan_info=61C99E70 Jun 18 05:39:37.625: CSM_PROC_OC3_COLLECT_ALL_DIGIT: CSM_EVENT_GET_ALL_DIGITS at slot 1, port 59 Jun 18 05:39:37.625: CSM_PROC_OC3_COLLECT_ALL_DIGIT: called party num: (6015) at slot 1, port 59 Jun 18 05:39:37.625: csm_get_signaling_channel dchan_index=24897,next_index=0 Jun 18 05:39:37.625: csm_get_signaling_channel dchan_info=61C99E70 Jun 18 05:39:37.625: ISDN Se0:15: TX -> SETUP pd = 8 callref = 0x000D Jun 18 05:39:37.625: Bearer Capability i = 0x8090A3 Jun 18 05:39:37.629: Channel ID i = 0xA9839F Jun 18 05:39:37.629: Called Party Number i = 0x81, '6015', Plan:ISDN, Type:Unknown Jun 18 05:39:37.665: ISDN Se0:15: RX <- CALL_PROC pd = 8 callref = 0x800D Jun 18 05:39:37.665: Channel ID i = 0xA9839F Jun 18 05:39:37.665: EVENT_FROM_ISDN::dchan_idb=0x61C99E70, call_id=0x800E, ces=0x1 bchan=0x1E, event=0x3, cause=0x0 Jun 18 05:39:37.665: EVENT_FROM_ISDN:(800E): DEV_CALL_PROC at slot 1 and port 59 Jun 18 05:39:37.665: CSM_PROC_OC4_DIALING: CSM_EVENT_ISDN_BCHAN_ASSIGNED at slot 1, port 59 Jun 18 05:39:37.665: Enter csm_connect_pri_vdev function Jun 18 05:39:37.665: csm_connect_pri_vdev:tdm_allocate_bp_ts() call. BP TS allocated at bp_stream0, bp_Ch13,vdev_common 0x6170A680 Jun 18 05:39:37.665: Mica Modem(1/59): Configure(0x1 = 0x1) Jun 18 05:39:37.665: Mica Modem(1/59): Configure(0x23 = 0x0) Jun 18 05:39:37.665: Mica Modem(1/59): Call Setup Jun 18 05:39:37.689: ISDN Se0:15: RX <- ALERTING pd = 8 callref = 0x800D Jun 18 05:39:37.693: EVENT_FROM_ISDN::dchan_idb=0x61C99E70, call_id=0x800E, ces=0x1 bchan=0x1E, event=0x10, cause=0x0 Jun 18 05:39:37.805: Mica Modem(1/59): State Transition to Call Setup Jun 18 05:39:38.797: As11 DDR: re-enable timeout Jun 18 05:39:39.753: ISDN Se0:15: RX <- CONNECT pd = 8 callref = 0x800D Jun 18 05:39:39.753: Progress Ind i = 0x8182 - Destination address is non-ISDN Jun 18 05:39:39.753: Connected Number i = 0xA136303135 Jun 18 05:39:39.753: Locking Shift to Codeset 6 Jun 18 05:39:39.753: Codeset 6 IE 0x28 i = 'Analog', 0x20, '15' Jun 18 05:39:39.757: EVENT_FROM_ISDN::dchan_idb=0x61C99E70, call_id=0x800E, ces=0x1 bchan=0x1E, event=0x4, cause=0x0 Jun 18 05:39:39.757: EVENT_FROM_ISDN:(800E): DEV_CONNECTED at slot 1 and port 59 Jun 18 05:39:39.757: CSM_PROC_OC5_WAIT_FOR_CARRIER: CSM_EVENT_ISDN_CONNECTED at slot 1, port 59 Jun 18 05:39:39.757: Mica Modem(1/59): Link Initiate Jun 18 05:39:39.757: %ISDN-6-CONNECT: Interface Serial0:30 is now connected to 6015 Jun 18 05:39:39.757: ISDN Se0:15: TX -> CONNECT_ACK pd = 8 callref = 0x000D Jun 18 05:39:39.845: Mica Modem(1/59): State Transition to Connect Jun 18 05:39:41.829: Mica Modem(1/59): State Transition to Link Jun 18 05:39:52.937: Mica Modem(1/59): State Transition to Trainup Jun 18 05:39:56.961: Mica Modem(1/59): State Transition to EC Negotiating Jun 18 05:39:57.081: Mica Modem(1/59): State Transition to Steady State Jun 18 05:39:57.081: CHAT60: Chat script d0efault-d0ials0cript finished, status = Success Jun 18 05:39:57.081: Unthrottle 60 Jun 18 05:39:57.081: TTY60: destroy timer type 1 Jun 18 05:39:57.081: TTY60: destroy timer type 0 Jun 18 05:39:57.081: As60 PPP: Async Protocol Mode started for 0.0.0.0 Jun 18 05:39:57.081: As60 AAA/ACCT: Using PPP accounting list "" Jun 18 05:39:57.129: As60 LCP: I CONFREQ [Closed] id 1 len 20 Jun 18 05:39:57.129: As60 LCP: ACCM 0x000A0000 (0x0206000A0000) Jun 18 05:39:57.129: As60 LCP: MagicNumber 0x1EF268EB (0x05061EF268EB) Jun 18 05:39:57.129: As60 LCP: PFC (0x0702) Jun 18 05:39:57.129: As60 LCP: ACFC (0x0802) Jun 18 05:39:57.129: As60 LCP: Lower layer not up, Fast Starting Jun 18 05:39:57.129: Di10: Session free, 28A0 Jun 18 05:39:57.129: : 0 packets unqueued and discarded Jun 18 05:39:57.129: As60 VPDN: Bind interface direction=1 Jun 18 05:39:57.129: As60 Tnl/Cl 41066/28 L2TP: Session state change from wait-cs-answer to established Jun 18 05:39:57.129: L2TP: Send OCCN Jun 18 05:39:57.133: As60 VPDN: bound to vpdn session Jun 18 05:39:57.133: As60 LCP: O TERMACK [Closed] id 1 len 4 Jun 18 05:39:57.133: As60 LCP: Dropping packet, state is Closed Jun 18 05:39:57.133: %LINK-3-UPDOWN: Interface Async60, changed state to up Jun 18 05:39:57.133: As60 DDR: Dialer statechange to up Jun 18 05:39:57.133: As60 DDR: Dialer call has been placed Jun 18 05:39:58.133: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async60, changed state to up Jun 18 05:40:00.129: As60 Tnl/Cl 41066/28 L2TP: I SLI from main-lns tnl 7118, cl 24 Jun 18 05:40:00.129: As60 Tnl/Cl 41066/28 L2TP: Get send ACCM 0x000A0000 and receive ACCM 0x000A0000
Incoming session on LNS for Async callback request:
*Jun 17 21:48:06.774: L2TP: I SCCRQ from main-lac tnl 63969 *Jun 17 21:48:06.774: Tnl 34677 L2TP: Got a challenge in SCCRQ, main-lac *Jun 17 21:48:06.774: Tnl 34677 L2TP: New tunnel created for remote main-lac, address 10.200.20.28 *Jun 17 21:48:06.774: Tnl 34677 L2TP: O SCCRP to main-lac tnlid 63969 *Jun 17 21:48:06.778: Tnl 34677 L2TP: Tunnel state change from idle to wait-ctl-reply *Jun 17 21:48:06.778: Tnl 34677 L2TP: I SCCCN from main-lac tnl 63969 *Jun 17 21:48:06.778: Tnl 34677 L2TP: Got a Challenge Response in SCCCNfrom main-lac *Jun 17 21:48:06.778: Tnl 34677 L2TP: Tunnel Authentication success *Jun 17 21:48:06.778: Tnl 34677 L2TP: Tunnel state change from wait-ctl-reply to established *Jun 17 21:48:06.782: Tnl 34677 L2TP: SM State established *Jun 17 21:48:06.782: Tnl 34677 L2TP: I ICRQ from main-lac tnl 63969 *Jun 17 21:48:06.782: Tnl/Cl 34677/21 L2TP: Session FS enabled *Jun 17 21:48:06.782: Tnl/Cl 34677/21 L2TP: Session state change from idle to wait-connect *Jun 17 21:48:06.782: Tnl/Cl 34677/21 L2TP: New session created *Jun 17 21:48:06.782: Tnl/Cl 34677/21 L2TP: O ICRP to main-lac 63969/25 *Jun 17 21:48:06.786: Tnl/Cl 34677/21 L2TP: I ICCN from main-lac tnl 63969, cl 25 *Jun 17 21:48:06.786: Tnl/Cl 34677/21 L2TP: Session state change from wait-connect to established *Jun 17 21:48:06.786: VPDN: Callback negotiated *Jun 17 21:48:06.786: Vi1 VTEMPLATE: Reuse Vi1, recycle queue size 0 *Jun 17 21:48:06.786: Vi1 VTEMPLATE: Hardware address 00e0.fe3f.4400 *Jun 17 21:48:06.786: Vi1 VPDN: Virtual interface created for Async@cb.com *Jun 17 21:48:06.786: Vi1 VPDN: Set to Async interface *Jun 17 21:48:06.786: Vi1 PPP: Phase is DOWN, Setup *Jun 17 21:48:06.786: Vi1 VPDN: Clone from Di1 *Jun 17 21:48:06.786: Vi1 VTEMPLATE: Has a new cloneblk dialer, now it has dialer *Jun 17 21:48:06.790: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up *Jun 17 21:48:06.790: Vi1 DDR: Dialer statechange to up *Jun 17 21:48:06.790: %FIB-4-PUNTINTF: CEF punting packets switched to Virtual-Access1 to next slower path *Jun 17 21:48:06.790: %DIALER-6-BIND: Interface Vi1 bound to profile Di1 *Jun 17 21:48:06.790: Vi1 PPP: Using set call direction *Jun 17 21:48:06.790: Vi1 PPP: Treating connection as a callin *Jun 17 21:48:06.790: Vi1 PPP: Phase is ESTABLISHING, Passive Open *Jun 17 21:48:06.790: Vi1 LCP: State is Listen *Jun 17 21:48:06.790: Vi1 VPDN: Bind interface direction=2 *Jun 17 21:48:06.790: Vi1 LCP: I FORCED CONFREQ len 21 *Jun 17 21:48:06.790: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:48:06.790: Vi1 LCP: AuthProto CHAP (0x0305C22305) *Jun 17 21:48:06.790: Vi1 LCP: MagicNumber 0x295DB486 (0x0506295DB486) *Jun 17 21:48:06.790: Vi1 LCP: PFC (0x0702) *Jun 17 21:48:06.790: Vi1 LCP: ACFC (0x0802) *Jun 17 21:48:06.794: Vi1 VPDN: PPP LCP accepted rcv CONFACK *Jun 17 21:48:06.794: Vi1 LCP: I FORCED CONFACK len 19 *Jun 17 21:48:06.794: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:48:06.794: Vi1 LCP: MagicNumber 0x1EECAEB9 (0x05061EECAEB9) *Jun 17 21:48:06.794: Vi1 LCP: PFC (0x0702) *Jun 17 21:48:06.794: Vi1 LCP: ACFC (0x0802) *Jun 17 21:48:06.794: Vi1 LCP: Callback 6 (0x0D0306) *Jun 17 21:48:06.794: Vi1 VPDN: PPP LCP accepted sent CONFACK *Jun 17 21:48:06.794: Vi1 PPP: Phase is AUTHENTICATING, by this end *Jun 17 21:48:06.794: Vi1 CHAP: O CHALLENGE id 3 len 25 from "fifi" *Jun 17 21:48:06.794: Vi1 CHAP: I RESPONSE id 1 len 34 from "Async@cb.com" *Jun 17 21:48:06.794: Vi1 CHAP: O SUCCESS id 1 len 4 *Jun 17 21:48:06.794: Vi1 MCB: User Async@cb.com Callback Number - Server6015 *Jun 17 21:48:06.794: Virtual-Access1 PPP: O MCB Request(1) id 14 len 7 *Jun 17 21:48:06.794: Virtual-Access1 MCB: O 1 E 0 7 3 3 0 *Jun 17 21:48:06.794: Vi1 MCB: O Request Id 14 Callback Type Server-Numdelay 0 *Jun 17 21:48:06.794: Vi1 PPP: Phase is CBCP *Jun 17 21:48:07.794: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access1, changed state to up *Jun 17 21:48:08.790: Vi1 LCP: TIMEout: State Open *Jun 17 21:48:08.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:08.794: Virtual-Access1 PPP: O MCB Request(1) id 15 len 7 *Jun 17 21:48:08.794: Virtual-Access1 MCB: O 1 F 0 7 3 3 0 *Jun 17 21:48:08.794: Vi1 MCB: O Request Id 15 Callback Type Server-Numdelay 0 *Jun 17 21:48:10.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:10.794: Virtual-Access1 PPP: O MCB Request(1) id 16 len 7 *Jun 17 21:48:10.794: Virtual-Access1 MCB: O 1 10 0 7 3 3 0 *Jun 17 21:48:10.794: Vi1 MCB: O Request Id 16 Callback Type Server-Numdelay 0 *Jun 17 21:48:12.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:12.794: Virtual-Access1 PPP: O MCB Request(1) id 17 len 7 *Jun 17 21:48:12.794: Virtual-Access1 MCB: O 1 11 0 7 3 3 0 *Jun 17 21:48:12.794: Vi1 MCB: O Request Id 17 Callback Type Server-Numdelay 0 *Jun 17 21:48:14.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:14.794: Virtual-Access1 PPP: O MCB Request(1) id 18 len 7 *Jun 17 21:48:14.794: Virtual-Access1 MCB: O 1 12 0 7 3 3 0 *Jun 17 21:48:14.794: Vi1 MCB: O Request Id 18 Callback Type Server-Numdelay 0 *Jun 17 21:48:15.510: %DEC21140-5-NOCARR: FastEthernet6/0 cable/connectorproblem? *Jun 17 21:48:16.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:16.794: Virtual-Access1 PPP: O MCB Request(1) id 19 len 7 *Jun 17 21:48:16.794: Virtual-Access1 MCB: O 1 13 0 7 3 3 0 *Jun 17 21:48:16.794: Vi1 MCB: O Request Id 19 Callback Type Server-Numdelay 0 *Jun 17 21:48:18.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:18.794: Virtual-Access1 PPP: O MCB Request(1) id 20 len 7 *Jun 17 21:48:18.794: Virtual-Access1 MCB: O 1 14 0 7 3 3 0 *Jun 17 21:48:18.794: Vi1 MCB: O Request Id 20 Callback Type Server-Numdelay 0 *Jun 17 21:48:20.666: Virtual-Access1 PPP: I MCB Response(2) id 14 len 7 *Jun 17 21:48:20.666: Virtual-Access1 MCB: I 2 E 0 7 3 3 F *Jun 17 21:48:20.666: Vi1 MCB: Received response *Jun 17 21:48:20.666: Vi1 MCB: Resp ignored. ID Expected 20, got id 14 *Jun 17 21:48:20.794: Vi1 MCB: Timeout in state WAIT_RESPONSE *Jun 17 21:48:20.794: Virtual-Access1 PPP: O MCB Request(1) id 21 len 7 *Jun 17 21:48:20.794: Virtual-Access1 MCB: O 1 15 0 7 3 3 0 *Jun 17 21:48:20.794: Vi1 MCB: O Request Id 21 Callback Type Server-Numdelay 0 *Jun 17 21:48:20.886: Virtual-Access1 PPP: I MCB Response(2) id 21 len 7 *Jun 17 21:48:20.886: Virtual-Access1 MCB: I 2 15 0 7 3 3 F *Jun 17 21:48:20.886: Vi1 MCB: Received response *Jun 17 21:48:20.886: Vi1 MCB: Response CBK-Server-Num 3 3 15 *Jun 17 21:48:20.890: Virtual-Access1 PPP: O MCB Ack(3) id 22 len 7 *Jun 17 21:48:20.890: Virtual-Access1 MCB: O 3 16 0 7 3 3 F *Jun 17 21:48:20.890: Vi1 MCB: O Ack Id 22 Callback Type Server-Num delay15 *Jun 17 21:48:20.890: Vi1 MCB: Negotiated MCB with peer *Jun 17 21:48:20.982: Vi1 LCP: I TERMREQ [Open] id 4 len 4 *Jun 17 21:48:20.982: Vi1 LCP: O TERMACK [Open] id 4 len 4 *Jun 17 21:48:20.986: Vi1 MCB: Peer terminating the link *Jun 17 21:48:22.986: Vi1 MCB: Timeout in state WAIT_LINKDOWN *Jun 17 21:48:22.986: Vi1 LCP: TIMEout: State TERMsent *Jun 17 21:48:22.986: Vi1 LCP: State is Closed *Jun 17 21:48:22.986: Vi1 MCB: Link terminated by peer, Callback Needed *Jun 17 21:48:22.986: Vi1 MCB: Initiate Callback for Async@cb.com at 6015using ISDN DDR *Jun 17 21:48:22.986: Vi1 DDR: PPP callback Callback server starting toAsync@cb.com 6015 *Jun 17 21:48:22.986: Vi1 VPDN: Cleanup*Jun 17 21:48:22.986: Vi1 VPDN: Reset *Jun 17 21:48:22.986: Vi1 Tnl/Cl 34677/21 L2TP: O CDN to main-lac 63969/25 *Jun 17 21:48:22.986: Vi1 Tnl/Cl 34677/21 L2TP: Destroying session *Jun 17 21:48:22.986: Vi1 Tnl/Cl 34677/21 L2TP: Session state change from established to idle *Jun 17 21:48:22.986: Vi1 Tnl/Cl 34677/21 L2TP: VPDN: Releasing idb for LAC/LNS tunnel 34677/63969 session 21 state idle *Jun 17 21:48:22.986: Vi1 VPDN: Reset *Jun 17 21:48:22.986: Tnl 34677 L2TP: Tunnel state change from established to no-sessions-left *Jun 17 21:48:22.986: Tnl 34677 L2TP: No more sessions in tunnel, shutdown (likely) in 10 seconds *Jun 17 21:48:22.986: Vi1 VPDN: Unbind interface *Jun 17 21:48:22.986: %DIALER-6-UNBIND: Interface Vi1 unbound from profileDi1 *Jun 17 21:48:22.990: Vi1 VTEMPLATE: Free vaccess *Jun 17 21:48:22.990: Vi1 VPDN: Unbind interface *Jun 17 21:48:22.990: Vi1 PPP: Phase is DOWN *Jun 17 21:48:22.990: Vi1 VPDN: Reset *Jun 17 21:48:22.990: Vi1 VPDN: Unbind interface *Jun 17 21:48:22.990: Vi1 PPP: Phase is ESTABLISHING, Passive Open *Jun 17 21:48:22.990: Vi1 PPP: No remote authentication for call-in *Jun 17 21:48:22.990: Vi1 LCP: State is Listen *Jun 17 21:48:22.990: VTEMPLATE: Clean up dirty vaccess queue, size 1 *Jun 17 21:48:22.990: Vi1 VTEMPLATE: Found a dirty vaccess clone withdialer *Jun 17 21:48:22.990: Vi1 VTEMPLATE: Remove cloneblk dialer with dialer *Jun 17 21:48:22.990: Vi1 VTEMPLATE: Set default settings with no ipaddress *Jun 17 21:48:22.994: %FIB-5-NOPUNTINTF: CEF resuming switching packets to Virtual-Access1 *Jun 17 21:48:23.018: Vi1 VTEMPLATE: Add vaccess to recycle queue, queuesize 1 *Jun 17 21:48:23.018: Vi1 LCP: State is Closed *Jun 17 21:48:23.018: Vi1 PPP: Phase is DOWN *Jun 17 21:48:23.986: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access1, changed state to down Closing session due to callback process : *Jun 17 21:48:32.986: Tnl 34677 L2TP: O StopCCN to main-lac tnlid 63969 *Jun 17 21:48:32.986: Tnl 34677 L2TP: Tunnel state change from no-sessions-left to shutting-down *Jun 17 21:48:32.986: Tnl 34677 L2TP: Shutdown tunnel *Jun 17 21:48:32.986: Tnl 34677 L2TP: Tunnel state change from shutting-down to idle Callback initiated : *Jun 17 21:48:37.986: DDR: Callback timer expired *Jun 17 21:48:37.986: Di1 DDR: beginning callback to Async@cb.com 6015 *Jun 17 21:48:37.986: Vi1 VTEMPLATE: Reuse Vi1, recycle queue size 0 *Jun 17 21:48:37.986: Vi1 VTEMPLATE: Hardware address 00e0.fe3f.4400 *Jun 17 21:48:37.986: Vi1 PPP: Phase is DOWN, Setup *Jun 17 21:48:37.986: Vi1 VTEMPLATE: Has a new cloneblk dialer, now it has dialer *Jun 17 21:48:37.986: Vi1 DDR: Dialing cause Callback return call *Jun 17 21:48:37.986: Vi1 DDR: Attempting to dial 6015 *Jun 17 21:48:37.986: Tnl/Cl 47336/22 L2TP: Session FS enabled *Jun 17 21:48:37.986: Tnl/Cl 47336/22 L2TP: Session state change from idle to wait-for-tunnel *Jun 17 21:48:37.986: Tnl/Cl 47336/22 L2TP: Create dialout session *Jun 17 21:48:37.986: Tnl 47336 L2TP: SM State idle *Jun 17 21:48:37.986: Tnl 47336 L2TP: O SCCRQ to main-lac tnlid 0 *Jun 17 21:48:37.986: Tnl 47336 L2TP: Tunnel state change from idle to wait-ctl-reply *Jun 17 21:48:37.986: Tnl 47336 L2TP: SM State wait-ctl-reply *Jun 17 21:48:37.986: Vi1 VPDN: Bind interface direction=2 *Jun 17 21:48:37.990: Tnl 47336 L2TP: I SCCRP from main-lac *Jun 17 21:48:37.990: Tnl 47336 L2TP: Got a challenge from remote peer, main-lac *Jun 17 21:48:37.990: Tnl 47336 L2TP: Got a response from remote peer, main-lac *Jun 17 21:48:37.990: Tnl 47336 L2TP: Tunnel Authentication success *Jun 17 21:48:37.994: Tnl 47336 L2TP: Tunnel state change from wait-ctl-reply to established *Jun 17 21:48:37.994: Tnl 47336 L2TP: O SCCCN to main-lac tnlid 12644 *Jun 17 21:48:37.994: Tnl 47336 L2TP: SM State established *Jun 17 21:48:37.994: L2TP: O OCRQ *Jun 17 21:48:37.994: Vi1 Tnl/Cl 47336/22 L2TP: Session state change from wait-for-tunnel to wait-reply *Jun 17 21:48:37.998: Vi1 Tnl/Cl 47336/22 L2TP: I OCRP from main-lac tnl12644, cl 0 *Jun 17 21:48:37.998: Vi1 Tnl/Cl 47336/22 L2TP: Session state change from wait-reply to wait-connect *Jun 17 21:48:45.510: %DEC21140-5-NOCARR: FastEthernet6/0 cable/connectorproblem? *Jun 17 21:48:58.282: Vi1 Tnl/Cl 47336/22 L2TP: I OCCN from main-lac tnl12644, cl 26 *Jun 17 21:48:58.282: Vi1 Tnl/Cl 47336/22 L2TP: Session state change from wait-connect to established *Jun 17 21:48:58.282: Vi1 VPDN: Connection is up, start LCP negotiation now *Jun 17 21:48:58.286: %LINK-3-UPDOWN: Interface Virtual-Access1, changedstate to up *Jun 17 21:48:58.286: Vi1 DDR: Dialer statechange to up *Jun 17 21:48:58.286: DDR: Freeing callback to Async@cb.com 6015 *Jun 17 21:48:58.286: %FIB-4-PUNTINTF: CEF punting packets switched to Virtual-Access1 to next slower path *Jun 17 21:48:58.286: %DIALER-6-BIND: Interface Vi1 bound to profile Di1 *Jun 17 21:48:58.286: Vi1 DDR: Dialer call has been placed *Jun 17 21:48:58.286: Vi1 PPP: Treating connection as a callout *Jun 17 21:48:58.286: Vi1 PPP: Phase is ESTABLISHING, Active Open *Jun 17 21:48:58.286: Vi1 LCP: O CONFREQ [Closed] id 1 len 25 *Jun 17 21:48:58.286: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:48:58.286: Vi1 LCP: AuthProto CHAP (0x0305C22305) *Jun 17 21:48:58.286: Vi1 LCP: MagicNumber 0xE9211538 (0x0506E9211538) *Jun 17 21:48:58.286: Vi1 LCP: PFC (0x0702) *Jun 17 21:48:58.286: Vi1 LCP: ACFC (0x0802) *Jun 17 21:48:58.410: Vi1 LCP: I CONFACK [REQsent] id 1 len 25 *Jun 17 21:48:58.410: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:48:58.410: Vi1 LCP: AuthProto CHAP (0x0305C22305) *Jun 17 21:48:58.410: Vi1 LCP: MagicNumber 0xE9211538 (0x0506E9211538) *Jun 17 21:48:58.410: Vi1 LCP: PFC (0x0702) *Jun 17 21:48:58.410: Vi1 LCP: ACFC (0x0802) *Jun 17 21:49:00.286: Vi1 LCP: TIMEout: State ACKrcvd *Jun 17 21:49:00.286: Vi1 LCP: O CONFREQ [ACKrcvd] id 2 len 25 *Jun 17 21:49:00.286: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:49:00.286: Vi1 LCP: AuthProto CHAP (0x0305C22305) *Jun 17 21:49:00.286: Vi1 LCP: MagicNumber 0xE9211538 (0x0506E9211538) *Jun 17 21:49:00.286: Vi1 LCP: PFC (0x0702) *Jun 17 21:49:00.286: Vi1 LCP: ACFC (0x0802) *Jun 17 21:49:00.378: Vi1 LCP: I CONFACK [REQsent] id 2 len 25 *Jun 17 21:49:00.378: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:49:00.378: Vi1 LCP: AuthProto CHAP (0x0305C22305) *Jun 17 21:49:00.378: Vi1 LCP: MagicNumber 0xE9211538 (0x0506E9211538) *Jun 17 21:49:00.378: Vi1 LCP: PFC (0x0702) *Jun 17 21:49:00.378: Vi1 LCP: ACFC (0x0802) *Jun 17 21:49:01.274: Vi1 LCP: I CONFREQ [ACKrcvd] id 2 len 20 *Jun 17 21:49:01.274: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:49:01.274: Vi1 LCP: MagicNumber 0x1EED8D53 (0x05061EED8D53) *Jun 17 21:49:01.274: Vi1 LCP: PFC (0x0702) *Jun 17 21:49:01.274: Vi1 LCP: ACFC (0x0802) *Jun 17 21:49:01.274: Vi1 LCP: O CONFACK [ACKrcvd] id 2 len 20 *Jun 17 21:49:01.274: Vi1 LCP: ACCM 0x000A0000 (0x0206000A0000) *Jun 17 21:49:01.274: Vi1 LCP: MagicNumber 0x1EED8D53 (0x05061EED8D53) *Jun 17 21:49:01.274: Vi1 LCP: PFC (0x0702) *Jun 17 21:49:01.274: Vi1 LCP: ACFC (0x0802) *Jun 17 21:49:01.278: Vi1 LCP: State is Open *Jun 17 21:49:01.278: Vi1 PPP: Phase is AUTHENTICATING, by this end *Jun 17 21:49:01.278: Vi1 CHAP: O CHALLENGE id 2 len 25 from "fifi" *Jun 17 21:49:01.278: Vi1 Tnl/Cl 47336/22 L2TP: Sending send ACCM0x000A0000 and receive ACCM 0x000A0000 *Jun 17 21:49:01.278: Vi1 Tnl/Cl 47336/22 L2TP: O SLI to main-lac 12644/26 *Jun 17 21:49:01.402: Vi1 CHAP: I RESPONSE id 2 len 34 from "Async@cb.com" *Jun 17 21:49:01.402: Vi1 CHAP: O SUCCESS id 2 len 4 *Jun 17 21:49:01.402: Vi1 PPP: Phase is UP *Jun 17 21:49:01.406: Vi1 IPCP: O CONFREQ [Not negotiated] id 1 len 10 *Jun 17 21:49:01.406: Vi1 IPCP: Address 1.1.1.1 (0x030601010101) *Jun 17 21:49:01.406: Vi1 CDPCP: O CONFREQ [Not negotiated] id 1 len 4 *Jun 17 21:49:01.498: Vi1 IPCP: I CONFREQ [REQsent] id 1 len 34 *Jun 17 21:49:01.498: Vi1 IPCP: Address 0.0.0.0 (0x030600000000) *Jun 17 21:49:01.498: Vi1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000) *Jun 17 21:49:01.498: Vi1 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000) *Jun 17 21:49:01.498: Vi1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000) *Jun 17 21:49:01.498: Vi1 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000) *Jun 17 21:49:01.498: Vi1 IPCP: Pool returned 1.100.0.1 *Jun 17 21:49:01.502: Vi1 IPCP: O CONFREJ [REQsent] id 1 len 22 *Jun 17 21:49:01.502: Vi1 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000) *Jun 17 21:49:01.502: Vi1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000) *Jun 17 21:49:01.502: Vi1 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000) *Jun 17 21:49:01.514: Vi1 IPCP: I CONFACK [REQsent] id 1 len 10 *Jun 17 21:49:01.514: Vi1 IPCP: Address 1.1.1.1 (0x030601010101) *Jun 17 21:49:01.518: Vi1 LCP: I PROTREJ [Open] id 3 len 10 protocol CDPCP(0x820701010004) *Jun 17 21:49:01.518: Vi1 CDPCP: State is Closed *Jun 17 21:49:01.594: Vi1 IPCP: I CONFREQ [ACKrcvd] id 2 len 16 *Jun 17 21:49:01.594: Vi1 IPCP: Address 0.0.0.0 (0x030600000000) *Jun 17 21:49:01.594: Vi1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000) *Jun 17 21:49:01.594: Vi1 IPCP: O CONFNAK [ACKrcvd] id 2 len 16 *Jun 17 21:49:01.594: Vi1 IPCP: Address 1.100.0.1 (0x030601640001) *Jun 17 21:49:01.594: Vi1 IPCP: PrimaryDNS 10.200.20.134(0x81060AC81486) *Jun 17 21:49:01.690: Vi1 IPCP: I CONFREQ [ACKrcvd] id 3 len 16 *Jun 17 21:49:01.690: Vi1 IPCP: Address 1.100.0.1 (0x030601640001) *Jun 17 21:49:01.690: Vi1 IPCP: PrimaryDNS 10.200.20.134(0x81060AC81486) *Jun 17 21:49:01.690: Vi1 IPCP: O CONFACK [ACKrcvd] id 3 len 16 *Jun 17 21:49:01.690: Vi1 IPCP: Address 1.100.0.1 (0x030601640001) *Jun 17 21:49:01.690: Vi1 IPCP: PrimaryDNS 10.200.20.134(0x81060AC81486) *Jun 17 21:49:01.694: Vi1 IPCP: State is Open *Jun 17 21:49:01.694: Vi1 DDR: dialer protocol up *Jun 17 21:49:01.694: Di1 IPCP: Install route to 1.100.0.1 *Jun 17 21:49:02.402: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access1, changed state to up *Jun 17 21:49:15.522: Vi1 PPP: Outbound cdp packet dropped, CDPCP is Closed[starting negotiations] *Jun 17 21:49:15.522: Vi1 CDPCP: State is Closed *Jun 17 21:49:15.530: Vi1 CDPCP: TIMEout: State Closed *Jun 17 21:49:15.530: Vi1 CDPCP: State is Listen
NetPro Discussion Forums - Featured Conversations
| NetPro Discussion Forums - Featured Conversations for Access |
| Network Infrastructure: Remote Access |
Related Information
| Updated: Jan 18, 2008 | Document ID: 6367 |
