Re: Multilink Callback with Virtual Template

jconi · ‎08-26-2003

Hello guys,

My problem is a little bit complicated. I've got a 3745 (IOS 12.2.13T5 IPbased) with a PRI and MICA modems. I configured a Remote Access solution with this 3745 and a Radius Server. Remote PCs can dialin in Async and ISDN mode. I configured also a callback but I have multilink problem with ISDN callback. This is my configuration:

ROUTER#sh run

Building configuration...

Current configuration : 2918 bytes

!

version 12.2

service timestamps debug datetime msec

service timestamps log datetime msec

no service password-encryption

!

hostname ROUTER

!

boot system flash flash:c3745-i-mz.122-13.T5.bin

logging buffered 4096 debugging

enable password <password>

!

username dialin password 0 <password>

aaa new-model

!

aaa group server radius radius-sg

server <ip_address> auth-port 1645 acct-port 1645

authorization reject reply-message

!

aaa authentication login LOCAL local

aaa authentication login dialout local

aaa authentication ppp dialin group radius-sg

aaa authorization network default group radius-sg

aaa session-id common

ip subnet-zero

!

no ip domain lookup

!

virtual-profile if-needed

virtual-profile virtual-template 1

multilink virtual-template 1

isdn switch-type primary-net5

!

chat-script offhook "" "ATH1" OK

chat-script callback ABORT ERROR ABORT BUSY "" "ATZ" OK "ATDT \T" TIMEOUT 60 CON

NECT \c

!

controller E1 1/0

pri-group timeslots 1-31

!

interface FastEthernet0/0

ip address <ip_address> 255.255.255.0

speed 100

full-duplex

!

interface FastEthernet0/1

no ip address

shutdown

duplex auto

speed auto

!

interface Serial1/0:15

ip unnumbered FastEthernet0/0

encapsulation ppp

dialer rotary-group 0

dialer-group 10

isdn switch-type primary-net5

isdn incoming-voice modem

no fair-queue

no cdp enable

ppp multilink

!

interface Virtual-Template1

ip unnumbered FastEthernet0/0

peer default ip address pool dialin_pool

ppp authentication pap chap dialin

ppp multilink

multilink load-threshold 1 either

!

interface Group-Async0

ip unnumbered FastEthernet0/0

encapsulation ppp

no ip mroute-cache

dialer in-band

dialer idle-timeout 600

dialer enable-timeout 6

dialer-group 10

async mode dedicated

peer default ip address pool dialin_pool

no keepalive

ppp callback permit

ppp authentication pap chap dialin

group-range 65 94

!

interface Dialer0

ip unnumbered FastEthernet0/0

encapsulation ppp

no ip mroute-cache

dialer in-band

dialer enable-timeout 2

dialer load-threshold 1 either

dialer-group 10

peer default ip address pool dialin_pool

no fair-queue

no cdp enable

ppp callback permit

ppp authentication pap chap dialin

ppp multilink

!

ip local pool dialin_pool <ip_address> <ip_address>

ip classless

ip route 0.0.0.0 0.0.0.0 <ip_address>

no ip http server

!

dialer-list 10 protocol ip permit

radius-server host <ip_address> auth-port 1645 acct-port 1645

radius-server timeout 2

radius-server attribute list reply-message

attribute 18

!

radius-server key <key>

radius-server authorization permit missing Service-Type

!

line con 0

line 65 94

flush-at-activation

script modem-off-hook offhook

script callback callback

login authentication dialout

modem InOut

modem autoconfigure discovery

rotary 69

transport input telnet

escape-character NONE

line aux 0

line vty 0 4

password <password>

!

end

I reproduced the problem in a Lab and made some tests. Instead of a PRI, I have a BRI in the Lab.

With the debugging, I can see that the callback on the second channel cannot start because there is already one started. I can also see that the Virtual Interface is requesting a second call when the load is above the load-threshold, but no call is attempted. I tried an another IOS in my Lab where the Dialer Profile can be cloned so we don't need Virtual Template, and in that case, the Router can initiate the second call. Why a call can be made when the Virtual-Profile clones the Dialer Profile, and not when it clones the Virtual Template.

Note that I need this IOS because I need to reject an attribute from the Radius which made the connection failing.

I post the debugs of a call when the multilink callback fails in the next post.

I'll really appreciate when someone could help me.

jp

jconi · ‎08-26-2003

The debug results when the multilink fails during callback:

ROUTER#sh debug

Dial on demand:

Dial on demand events debugging is on

VPROFILE:

Virtual Profile debugging is on

PPP:

PPP authentication debugging is on

PPP protocol negotiation debugging is on

Multilink fragments debugging is on

Multilink events debugging is on

First bytes of multilink packet debugging is on

The following ISDN debugs are enabled on all DSLs:

debug isdn error is ON.

debug isdn q931 is ON.

VTEMPLATE:

Virtual Template events debugging is on

Virtual Template errors debugging is on

Virtual Template cloning debugging is on

Virtual Template subinterface debugging is on

ROUTER#

*Mar 18 06:54:18.833: ISDN Se1/0:15 Q931: RX <- SETUP pd = 8 callref = 0x60F1

Sending Complete

Bearer Capability i = 0x8890

Standard = CCITT

Transer Capability = Unrestricted Digital

Transfer Mode = Circuit

Transfer Rate = 64 kbit/s

Channel ID i = 0xA9839E

Exclusive, Channel 30

Calling Party Number i = 0x00, 0x81, '26151586'

Plan:Unknown, Type:Unknown

*Mar 18 06:54:18.857: %LINK-3-UPDOWN: Interface Serial1/0:29, changed state to up

*Mar 18 06:54:18.861: ISDN Se1/0:15 Q931: TX -> CALL_PROC pd = 8 callref = 0xE0F1

Channel ID i = 0xA9839E

Exclusive, Channel 30

*Mar 18 06:54:18.861: ISDN Se1/0:15 Q931: TX -> CONNECT pd = 8 callref = 0xE0F1

Channel ID i = 0xA9839E

Exclusive, Channel 30

*Mar 18 06:54:18.861: Se1/0:29 PPP: Using dialer call direction

*Mar 18 06:54:18.861: Se1/0:29 PPP: Treating connection as a callin

*Mar 18 06:54:18.861: Se1/0:29 PPP: Phase is ESTABLISHING, Passive Open

*Mar 18 06:54:18.861: Se1/0:29 LCP: State is Listen

*Mar 18 06:54:18.861: ISDN Se1/0:15 Q931: RX <- SETUP pd = 8 callref = 0x60F2

Sending Complete

Bearer Capability i = 0x8890

Standard = CCITT

Transer Capability = Unrestricted Digital

Transfer Mode = Circuit

Transfer Rate = 64 kbit/s

Channel ID i = 0xA9839C

Exclusive, Channel 28

Calling Party Number i = 0x00, 0x81, '26151586'

Plan:Unknown, Type:Unknown

*Mar 18 06:54:18.885: %LINK-3-UPDOWN: Interface Serial1/0:27, changed state to up

*Mar 18 06:54:18.885: %ISDN-6-CONNECT: Interface Serial1/0:29 is now connected to 26151586

*Mar 18 06:54:18.889: ISDN Se1/0:15 Q931: TX -> CALL_PROC pd = 8 callref = 0xE0F2

Channel ID i = 0xA9839C

Exclusive, Channel 28

*Mar 18 06:54:18.889: ISDN Se1/0:15 Q931: TX -> CONNECT pd = 8 callref = 0xE0F2

Channel ID i = 0xA9839C

Exclusive, Channel 28

*Mar 18 06:54:18.889: Se1/0:27 PPP: Using dialer call direction

*Mar 18 06:54:18.889: Se1/0:27 PPP: Treating connection as a callin

*Mar 18 06:54:18.889: Se1/0:27 PPP: Phase is ESTABLISHING, Passive Open

*Mar 18 06:54:18.889: Se1/0:27 LCP: State is Listen

*Mar 18 06:54:18.945: ISDN Se1/0:15 Q931: RX <- CONNECT_ACK pd = 8 callref = 0x60F1

*Mar 18 06:54:18.961: ISDN Se1/0:15 Q931: RX <- CONNECT_ACK pd = 8 callref = 0x60F2

*Mar 18 06:54:19.233: Se1/0:29 LCP: I CONFREQ [Listen] id 0 len 30

*Mar 18 06:54:19.233: Se1/0:29 LCP: MagicNumber 0x200A68CF (0x0506200A68CF)

*Mar 18 06:54:19.233: Se1/0:29 LCP: PFC (0x0702)

*Mar 18 06:54:19.233: Se1/0:29 LCP: ACFC (0x0802)

*Mar 18 06:54:19.233: Se1/0:29 LCP: Callback 6 (0x0D0306)

*Mar 18 06:54:19.233: Se1/0:29 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:19.233: Se1/0:29 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:19.233: Se1/0:29 PPP: Authorization required

*Mar 18 06:54:19.233: Se1/0:29 LCP: O CONFREQ [Listen] id 107 len 32

*Mar 18 06:54:19.233: Se1/0:29 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:19.233: Se1/0:29 LCP: MagicNumber 0x5B32EE2A (0x05065B32EE2A)

*Mar 18 06:54:19.233: Se1/0:29 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:19.233: Se1/0:29 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:19.233: Se1/0:29 LCP: O CONFACK [Listen] id 0 len 30

*Mar 18 06:54:19.233: Se1/0:29 LCP: MagicNumber 0x200A68CF (0x0506200A68CF)

*Mar 18 06:54:19.233: Se1/0:29 LCP: PFC (0x0702)

*Mar 18 06:54:19.233: Se1/0:29 LCP: ACFC (0x0802)

*Mar 18 06:54:19.233: Se1/0:29 LCP: Callback 6 (0x0D0306)

*Mar 18 06:54:19.233: Se1/0:29 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:19.233: Se1/0:29 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:19.253: Se1/0:29 LCP: I CONFACK [ACKsent] id 107 len 32

*Mar 18 06:54:19.253: Se1/0:29 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:19.253: Se1/0:29 LCP: MagicNumber 0x5B32EE2A (0x05065B32EE2A)

*Mar 18 06:54:19.253: Se1/0:29 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:19.253: Se1/0:29 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:19.253: Se1/0:29 LCP: State is Open

*Mar 18 06:54:19.253: Se1/0:29 PPP: Phase is AUTHENTICATING, by this end

*Mar 18 06:54:19.257: Se1/0:29 LCP: I IDENTIFY [Open] id 1 len 18 magic 0x200A68CF MSRASV5.00

*Mar 18 06:54:19.261: Se1/0:29 LCP: I IDENTIFY [Open] id 2 len 22 magic 0x200A68

CF MSRAS-1-CONIJP

*Mar 18 06:54:19.261: Se1/0:29 PAP: I AUTH-REQ id 50 len 17 from "test"

*Mar 18 06:54:19.261: Se1/0:29 PAP: Authenticating peer test

*Mar 18 06:54:19.261: Se1/0:29 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:19.261: Se1/0:29 PPP: Phase is AUTHENTICATING, Unauthenticated User

*Mar 18 06:54:19.265: Se1/0:29 PPP: Sent PAP LOGIN Request

*Mar 18 06:54:19.333: Se1/0:29 PPP: Received LOGIN Response PASS

*Mar 18 06:54:19.333: Se1/0:29 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:19.333: Se1/0:29 PPP: Phase is AUTHENTICATING, Authenticated User

*Mar 18 06:54:19.333: Se1/0:29 DDR: Remote name for test

*Mar 18 06:54:19.333: Se1/0:29 DDR: Authenticated host test with no matching dialer map

*Mar 18 06:54:19.333: Se1/0:29 PAP: O AUTH-ACK id 50 len 5

*Mar 18 06:54:19.333: Se1/0:29 MCB: User test Callback Number - Client ANY

*Mar 18 06:54:19.333: Se1/0:29 PPP: O MCB Request(1) id 80 len 11

*Mar 18 06:54:19.333: Se1/0:29 MCB: O 1 50 0 B 1 2 2 5 0 1 0

*Mar 18 06:54:19.333: Se1/0:29 MCB: O Request Id 80 Callback Types Client-Num and None delay 0

*Mar 18 06:54:19.333: Se1/0:29 PPP: Phase is CBCP

*Mar 18 06:54:20.333: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial1/0:29, changed state to up

*Mar 18 06:54:20.569: Se1/0:29 PPP: I MCB Response(2) id 80 len 17

*Mar 18 06:54:20.569: Se1/0:29 MCB: I 2 50 0 11 2 D A 1 32 36 31 35 31 35 38 36 0

*Mar 18 06:54:20.569: Se1/0:29 MCB: Received response

*Mar 18 06:54:20.569: Se1/0:29 MCB: Response CBK-Client-Num 2 13 10, addr 1-26151586

*Mar 18 06:54:20.569: Se1/0:29 PPP: O MCB Ack(3) id 80 len 17

*Mar 18 06:54:20.569: Se1/0:29 MCB: O 3 50 0 11 2 D A 1 32 36 31 35 31 35 38 36 0

*Mar 18 06:54:20.569: Se1/0:29 MCB: O Ack Id 80 Callback Type Client-Num delay 10

*Mar 18 06:54:20.569: Se1/0:29 MCB: Negotiated MCB with peer

*Mar 18 06:54:20.585: Se1/0:29 LCP: I TERMREQ [Open] id 3 len 16 (0x200A68CF003CCD7400000000)

*Mar 18 06:54:20.585: Se1/0:29 LCP: O TERMACK [Open] id 3 len 4

*Mar 18 06:54:20.585: Se1/0:29 MCB: Peer terminating the link

*Mar 18 06:54:20.585: Se1/0:29 PPP: Sending Acct Event[Down] id[23B]

*Mar 18 06:54:20.585: Se1/0:29 MCB: Link terminated by peer, Callback Needed

*Mar 18 06:54:20.585: Se1/0:29 MCB: Initiate Callback for test at 26151586 using ISDN DDR

*Mar 18 06:54:20.585: Se1/0:29 DDR: PPP callback: Callback server starting to test 26151586

*Mar 18 06:54:20.589: Se1/0:29 PPP: Phase is TERMINATING

*Mar 18 06:54:20.805: ISDN Se1/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x60F1

Cause i = 0x8190 - Normal call clearing

*Mar 18 06:54:20.805: %ISDN-6-CONNECT: Interface Serial1/0:27 is now connected to 26151586

*Mar 18 06:54:20.805: %ISDN-6-DISCONNECT: Interface Serial1/0:29 disconnected from 26151586 test, call lasted 1 seconds

*Mar 18 06:54:20.841: %LINK-3-UPDOWN: Interface Serial1/0:29, changed state to down

*Mar 18 06:54:20.841: ISDN Se1/0:15 Q931: TX -> RELEASE pd = 8 callref = 0xE0F1

*Mar 18 06:54:20.841: Se1/0:29 LCP: State is Closed

*Mar 18 06:54:20.841: Se1/0:29 PPP: Phase is DOWN

*Mar 18 06:54:20.841: Se1/0:29 DDR: disconnecting call

*Mar 18 06:54:20.861: Se1/0:27 LCP: TIMEout: State Listen

*Mar 18 06:54:20.861: Se1/0:27 PPP: Authorization required

*Mar 18 06:54:20.861: Se1/0:27 LCP: O CONFREQ [Listen] id 18 len 32

*Mar 18 06:54:20.861: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:20.861: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:20.861: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:20.861: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

jconi · ‎08-26-2003

*Mar 18 06:54:20.861: ISDN Se1/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x60F1

*Mar 18 06:54:21.585: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial1/0:29, changed state to down

*Mar 18 06:54:22.585: DDR: Callback timer expired

*Mar 18 06:54:22.585: Di0 DDR: beginning callback to test 26151586

*Mar 18 06:54:22.585: Se1/0:15 DDR: rotor dialout [priority]

*Mar 18 06:54:22.585: Se1/0:15 DDR: Attempting to dial 26151586

*Mar 18 06:54:22.585: ISDN Se1/0:15 Q931: TX -> SETUP pd = 8 callref = 0x004E

Bearer Capability i = 0x8890

Standard = CCITT

Transer Capability = Unrestricted Digital

Transfer Mode = Circuit

Transfer Rate = 64 kbit/s

Channel ID i = 0xA9839E

Exclusive, Channel 30

Called Party Number i = 0x81, '26151586'

Plan:ISDN, Type:Unknown

*Mar 18 06:54:22.645: ISDN Se1/0:15 Q931: RX <- SETUP_ACK pd = 8 callref = 0x804E

Channel ID i = 0xA9839E

Exclusive, Channel 30

*Mar 18 06:54:22.877: Se1/0:27 LCP: TIMEout: State REQsent

*Mar 18 06:54:22.877: Se1/0:27 LCP: O CONFREQ [REQsent] id 19 len 32

*Mar 18 06:54:22.877: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:22.877: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:22.877: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:22.877: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:23.229: ISDN Se1/0:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x804E

*Mar 18 06:54:23.309: ISDN Se1/0:15 Q931: RX <- ALERTING pd = 8 callref = 0x804E

*Mar 18 06:54:24.893: Se1/0:27 LCP: TIMEout: State REQsent

*Mar 18 06:54:24.893: Se1/0:27 LCP: O CONFREQ [REQsent] id 20 len 32

*Mar 18 06:54:24.893: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:24.893: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:24.893: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:24.893: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:26.861: Se1/0:27 LCP: I CONFREQ [REQsent] id 0 len 30

*Mar 18 06:54:26.861: Se1/0:27 LCP: MagicNumber 0x016173B1 (0x0506016173B1)

*Mar 18 06:54:26.861: Se1/0:27 LCP: PFC (0x0702)

*Mar 18 06:54:26.861: Se1/0:27 LCP: ACFC (0x0802)

*Mar 18 06:54:26.861: Se1/0:27 LCP: Callback 6 (0x0D0306)

*Mar 18 06:54:26.861: Se1/0:27 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:26.861: Se1/0:27 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:26.861: Se1/0:27 LCP: O CONFACK [REQsent] id 0 len 30

*Mar 18 06:54:26.865: Se1/0:27 LCP: MagicNumber 0x016173B1 (0x0506016173B1)

*Mar 18 06:54:26.865: Se1/0:27 LCP: PFC (0x0702)

*Mar 18 06:54:26.865: Se1/0:27 LCP: ACFC (0x0802)

*Mar 18 06:54:26.865: Se1/0:27 LCP: Callback 6 (0x0D0306)

*Mar 18 06:54:26.865: Se1/0:27 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:26.865: Se1/0:27 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:26.869: Se1/0:27 LCP: I CONFACK [ACKsent] id 18 len 32

*Mar 18 06:54:26.869: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:26.869: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:26.869: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:26.869: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:26.869: Se1/0:27 LCP: ID 18 didn't match 20, discarding packet

*Mar 18 06:54:26.873: Se1/0:27 LCP: I CONFACK [ACKsent] id 19 len 32

*Mar 18 06:54:26.873: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:26.873: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:26.873: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:26.873: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:26.873: Se1/0:27 LCP: ID 19 didn't match 20, discarding packet

*Mar 18 06:54:26.877: Se1/0:27 LCP: I CONFACK [ACKsent] id 20 len 32

*Mar 18 06:54:26.877: Se1/0:27 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:26.877: Se1/0:27 LCP: MagicNumber 0x5B32F488 (0x05065B32F488)

*Mar 18 06:54:26.877: Se1/0:27 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:26.877: Se1/0:27 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:26.877: Se1/0:27 LCP: State is Open

*Mar 18 06:54:26.877: Se1/0:27 PPP: Phase is AUTHENTICATING, by this end

*Mar 18 06:54:26.881: Se1/0:27 LCP: I IDENTIFY [Open] id 1 len 18 magic 0x016173B1 MSRASV5.00

*Mar 18 06:54:26.885: Se1/0:27 LCP: I IDENTIFY [Open] id 2 len 22 magic 0x016173B1 MSRAS-1-CONIJP

*Mar 18 06:54:26.889: Se1/0:27 PAP: I AUTH-REQ id 51 len 17 from "test"

*Mar 18 06:54:26.889: Se1/0:27 PAP: Authenticating peer test

*Mar 18 06:54:26.889: Se1/0:27 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:26.889: Se1/0:27 PPP: Phase is AUTHENTICATING, Unauthenticated User

*Mar 18 06:54:26.889: Se1/0:27 PPP: Sent PAP LOGIN Request

*Mar 18 06:54:26.965: Se1/0:27 PPP: Received LOGIN Response PASS

*Mar 18 06:54:26.965: Se1/0:27 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:26.965: Se1/0:27 PPP: Phase is AUTHENTICATING, Authenticated User

*Mar 18 06:54:26.965: Se1/0:27 DDR: Remote name for test

*Mar 18 06:54:26.965: Se1/0:27 PAP: O AUTH-ACK id 51 len 5

*Mar 18 06:54:26.965: Se1/0:27 MCB: User test Callback Number - Client ANY

*Mar 18 06:54:26.965: Se1/0:27 PPP: O MCB Request(1) id 7 len 11

*Mar 18 06:54:26.965: Se1/0:27 MCB: O 1 7 0 B 1 2 2 5 0 1 0

*Mar 18 06:54:26.965: Se1/0:27 MCB: O Request Id 7 Callback Types Client-Num and None delay 0

*Mar 18 06:54:26.965: Se1/0:27 PPP: Phase is CBCP

*Mar 18 06:54:26.985: Se1/0:27 PPP: I MCB Response(2) id 7 len 17

*Mar 18 06:54:26.985: Se1/0:27 MCB: I 2 7 0 11 2 D A 1 32 36 31 35 31 35 38 36 0

*Mar 18 06:54:26.985: Se1/0:27 MCB: Received response

*Mar 18 06:54:26.985: Se1/0:27 MCB: Response CBK-Client-Num 2 13 10, addr 1-26151586

*Mar 18 06:54:26.985: Se1/0:27 PPP: O MCB Ack(3) id 7 len 17

*Mar 18 06:54:26.985: Se1/0:27 MCB: O 3 7 0 11 2 D A 1 32 36 31 35 31 35 38 36 0

*Mar 18 06:54:26.985: Se1/0:27 MCB: O Ack Id 7 Callback Type Client-Num delay 10

*Mar 18 06:54:26.985: Se1/0:27 MCB: Negotiated MCB with peer

*Mar 18 06:54:27.001: Se1/0:27 LCP: I TERMREQ [Open] id 3 len 16 (0x016173B1003CCD7400000000)

*Mar 18 06:54:27.001: Se1/0:27 LCP: O TERMACK [Open] id 3 len 4

*Mar 18 06:54:27.001: Se1/0:27 MCB: Peer terminating the link

*Mar 18 06:54:27.001: Se1/0:27 PPP: Sending Acct Event[Down] id[23C]

*Mar 18 06:54:27.001: Se1/0:27 MCB: Link terminated by peer, Callback Needed

*Mar 18 06:54:27.001: Se1/0:27 MCB: Initiate Callback for test at 26151586 using ISDN DDR

*Mar 18 06:54:27.001: Se1/0:27 DDR: callback to test already started

*Mar 18 06:54:27.001: Se1/0:27 PPP: Phase is TERMINATING

*Mar 18 06:54:27.117: ISDN Se1/0:15 Q931: RX <- CONNECT pd = 8 callref = 0x804E

Date/Time i = 0x0308161115

Connected Number i = 0x00803236313531353836

*Mar 18 06:54:27.141: %LINK-3-UPDOWN: Interface Serial1/0:29, changed state to up

*Mar 18 06:54:27.141: Se1/0:29 DDR: Copying MS callback dialstring 26151586 to ddb

*Mar 18 06:54:27.141: DDR: Freeing callback to test 26151586

*Mar 18 06:54:27.141: ISDN Se1/0:15 Q931: RX <- FACILITY pd = 8 callref = 0x804E

Facility i = 0x91A11302024F38020122300AA1053003020101820100

- ETSI Supplementary Service, Invoke, AOC-D Charging Units: 1

*Mar 18 06:54:27.141: ISDN Se1/0:15 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x004E

*Mar 18 06:54:27.141: Se1/0:29 PPP: Using dialer call direction

*Mar 18 06:54:27.141: Se1/0:29 PPP: Treating connection as a callout

*Mar 18 06:54:27.141: Se1/0:29 PPP: Phase is ESTABLISHING, Active Open

*Mar 18 06:54:27.141: Se1/0:29 PPP: Authorization required

*Mar 18 06:54:27.141: Se1/0:29 LCP: O CONFREQ [Closed] id 108 len 32

*Mar 18 06:54:27.141: Se1/0:29 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:27.141: Se1/0:29 LCP: MagicNumber 0x5B330D12 (0x05065B330D12)

*Mar 18 06:54:27.141: Se1/0:29 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:27.141: Se1/0:29 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:27.165: Se1/0:29 LCP: I CONFACK [REQsent] id 108 len 32

*Mar 18 06:54:27.165: Se1/0:29 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:27.165: Se1/0:29 LCP: MagicNumber 0x5B330D12 (0x05065B330D12)

*Mar 18 06:54:27.165: Se1/0:29 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:27.165: Se1/0:29 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:27.249: ISDN Se1/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x60F2

Cause i = 0x8190 - Normal call clearing

*Mar 18 06:54:27.249: %ISDN-6-CONNECT: Interface Serial1/0:29 is now connected to 26151586

*Mar 18 06:54:27.249: %ISDN-6-DISCONNECT: Interface Serial1/0:27 disconnected from 26151586 test, call lasted 8 seconds

*Mar 18 06:54:27.285: %LINK-3-UPDOWN: Interface Serial1/0:27, changed state to down

*Mar 18 06:54:27.285: ISDN Se1/0:15 Q931: TX -> RELEASE pd = 8 callref = 0xE0F2

*Mar 18 06:54:27.285: Se1/0:27 LCP: State is Closed

*Mar 18 06:54:27.285: Se1/0:27 PPP: Phase is DOWN

*Mar 18 06:54:27.285: Se1/0:27 DDR: disconnecting call

jconi · ‎08-26-2003

*Mar 18 06:54:27.305: ISDN Se1/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x60F2

*Mar 18 06:54:28.865: Se1/0:29 LCP: I CONFREQ [ACKrcvd] id 1 len 27

*Mar 18 06:54:28.865: Se1/0:29 LCP: MagicNumber 0x016173B1 (0x0506016173B1)

*Mar 18 06:54:28.865: Se1/0:29 LCP: PFC (0x0702)

*Mar 18 06:54:28.865: Se1/0:29 LCP: ACFC (0x0802)

*Mar 18 06:54:28.865: Se1/0:29 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:28.865: Se1/0:29 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:28.865: Se1/0:29 LCP: O CONFACK [ACKrcvd] id 1 len 27

*Mar 18 06:54:28.865: Se1/0:29 LCP: MagicNumber 0x016173B1 (0x0506016173B1)

*Mar 18 06:54:28.865: Se1/0:29 LCP: PFC (0x0702)

*Mar 18 06:54:28.865: Se1/0:29 LCP: ACFC (0x0802)

*Mar 18 06:54:28.865: Se1/0:29 LCP: MRRU 1614 (0x1104064E)

*Mar 18 06:54:28.865: Se1/0:29 LCP: EndpointDisc 3 e0d1.2052.4153 (0x130903E0D120524153)

*Mar 18 06:54:28.865: Se1/0:29 LCP: State is Open

*Mar 18 06:54:28.865: Se1/0:29 PPP: Phase is AUTHENTICATING, by this end

*Mar 18 06:54:28.881: Se1/0:29 LCP: I IDENTIFY [Open] id 2 len 18 magic 0x016173B1 MSRASV5.00

*Mar 18 06:54:28.885: Se1/0:29 LCP: I IDENTIFY [Open] id 3 len 22 magic 0x016173B1 MSRAS-1-CONIJP

*Mar 18 06:54:28.889: Se1/0:29 PAP: I AUTH-REQ id 52 len 17 from "test"

*Mar 18 06:54:28.889: Se1/0:29 PAP: Authenticating peer test

*Mar 18 06:54:28.889: Se1/0:29 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:28.889: Se1/0:29 PPP: Phase is AUTHENTICATING, Unauthenticated User

*Mar 18 06:54:28.889: Se1/0:29 PPP: Sent PAP LOGIN Request

*Mar 18 06:54:28.945: Se1/0:29 PPP: Received LOGIN Response PASS

*Mar 18 06:54:28.945: Se1/0:29 PPP: Phase is FORWARDING, Attempting Forward

*Mar 18 06:54:28.945: Se1/0:29 PPP: Phase is AUTHENTICATING, Authenticated User

*Mar 18 06:54:28.945: Se1/0:29 DDR: Remote name for test

*Mar 18 06:54:28.945: Se1/0:29 DDR: Authenticated host test with no matching dialer map

*Mar 18 06:54:28.945: Se1/0:29 PAP: O AUTH-ACK id 52 len 5

*Mar 18 06:54:28.945: Se1/0:29 MLP: Request add link to bundle

*Mar 18 06:54:28.945: Se1/0:29 PPP: Phase is VIRTUALIZED

*Mar 18 06:54:28.945: Se1/0:29 MLP: Adding link to bundle

*Mar 18 06:54:28.945: VT[Vi5]:Reuse interface, recycle queue size 3

*Mar 18 06:54:28.945: VT[Vi5]:Set to default using 'encap ppp'

*Mar 18 06:54:28.945: VT[Vi5]:Vaccess created

*Mar 18 06:54:28.949: Vi5 MLP: VP: Clone from Vtemplate 1 block=0

*Mar 18 06:54:28.949: VT[Vi5]:Added new vtemplate cloneblk, now cloning from vtemplate

*Mar 18 06:54:28.949: VT[Vi5]:ip unnumbered FastEthernet0/0

*Mar 18 06:54:28.949: VT[Vi5]:Virtual-Template1 has no command strings to clone

*Mar 18 06:54:28.949: Vi5 MLP: VP: Clone from AAA

*Mar 18 06:54:28.949: VT[Vi5]:Added new AAA cloneblk, now cloning from vtemplate/AAA

*Mar 18 06:54:28.949: VT[Vi5]:Clone Vaccess from AAA (31 bytes)

*Mar 18 06:54:28.949: VT[Vi5]:ip tcp header-compression

*Mar 18 06:54:28.949: VT[Vi5]:end

*Mar 18 06:54:28.949: VT[Vi5]:Applying config commands on process "Multilink event" (77)

*Mar 18 06:54:28.949: VT[Vi5]:ip tcp header-compression

*Mar 18 06:54:28.949: VT[Vi5]:end

*Mar 18 06:54:28.949: Vi5 PPP: Outbound context-status packet dropped, line protocol not up

*Mar 18 06:54:28.949: VT[Vi5]:Bringing up interface

*Mar 18 06:54:28.949: Vi5 PPP: Phase is DOWN, Setup

*Mar 18 06:54:28.949: Vi5 PPP: Using default call direction

*Mar 18 06:54:28.949: Vi5 PPP: Treating connection as a dedicated line

*Mar 18 06:54:28.949: Vi5 PPP: Phase is ESTABLISHING, Active Open

*Mar 18 06:54:28.949: Vi5 PPP: Authorization required

*Mar 18 06:54:28.949: Vi5 LCP: O CONFREQ [Closed] id 1 len 32

*Mar 18 06:54:28.949: Vi5 LCP: AuthProto PAP (0x0304C023)

*Mar 18 06:54:28.949: Vi5 LCP: MagicNumber 0x5B331424 (0x05065B331424)

*Mar 18 06:54:28.949: Vi5 LCP: MRRU 1524 (0x110405F4)

*Mar 18 06:54:28.949: Vi5 LCP: EndpointDisc 1 NAS_DIALOUT (0x130E014E41535F4449414C4F5554)

*Mar 18 06:54:28.953: %LINK-3-UPDOWN: Interface Virtual-Access5, changed state to up

*Mar 18 06:54:28.953: Vi5 MLP: Lost frag timeout too low for slippage constraints, increasing to 1524 ms

*Mar 18 06:54:28.953: Vi5 MLP: Added first link Se1/0:29 to bundle test

*Mar 18 06:54:28.953: Vi5 PPP: Phase is UP

*Mar 18 06:54:28.953: Vi5 IPCP: O CONFREQ [Closed] id 1 len 16

*Mar 18 06:54:28.953: Vi5 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

*Mar 18 06:54:28.953: Vi5 IPCP: Address 194.36.238.190 (0x0306C224EEBE)

*Mar 18 06:54:28.953: Se1/0:29 MLP: O ppp IPCP (8021) size 20 via oqueue

*Mar 18 06:54:28.953: Vi5 PPP: Process pending packets

*Mar 18 06:54:28.953: Se1/0:29 PPP: Process pending packets

*Mar 18 06:54:28.961: Vi5 CCP: I CONFREQ [Not negotiated] id 4 len 10

*Mar 18 06:54:28.961: Vi5 CCP: MS-PPC supported bits 0x00000001 (0x120600000001)

*Mar 18 06:54:28.961: Vi5 LCP: O PROTREJ [Open] id 2 len 16 protocol CCP (0x80FD0104000A120600000001)

*Mar 18 06:54:28.961: Se1/0:29 MLP: O ppp LCP (C021) size 20 via oqueue

*Mar 18 06:54:28.969: Vi5 IPCP: I CONFREQ [REQsent] id 5 len 40

*Mar 18 06:54:28.969: Vi5 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)

*Mar 18 06:54:28.969: Vi5 IPCP: Address 0.0.0.0 (0x030600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)

*Mar 18 06:54:28.969: Vi5 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0, we want 0.0.0.0

*Mar 18 06:54:28.969: Vi5 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want 0.0.0.0

*Mar 18 06:54:28.969: Vi5 IPCP: Pool returned 192.168.203.2

*Mar 18 06:54:28.969: Vi5 IPCP: O CONFREJ [REQsent] id 5 len 28

*Mar 18 06:54:28.969: Vi5 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)

*Mar 18 06:54:28.969: Vi5 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)

*Mar 18 06:54:28.969: Se1/0:29 MLP: O ppp IPCP (8021) size 32 via oqueue

*Mar 18 06:54:28.969: Vi5 IPCP: I CONFACK [REQsent] id 1 len 16

*Mar 18 06:54:28.969: Vi5 IPCP: CompressType VJ 15 slots (0x0206002D0F00)

*Mar 18 06:54:28.973: Vi5 IPCP: Address 194.36.238.190 (0x0306C224EEBE)

*Mar 18 06:54:28.989: Vi5 IPCP: I CONFREQ [ACKrcvd] id 6 len 16

*Mar 18 06:54:28.989: Vi5 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)

*Mar 18 06:54:28.989: Vi5 IPCP: Address 0.0.0.0 (0x030600000000)

*Mar 18 06:54:28.989: Vi5 IPCP: O CONFNAK [ACKrcvd] id 6 len 10

*Mar 18 06:54:28.989: Vi5 IPCP: Address 192.168.203.2 (0x0306C0A8CB02)

*Mar 18 06:54:28.989: Se1/0:29 MLP: O ppp IPCP (8021) size 14 via oqueue

*Mar 18 06:54:29.005: Vi5 IPCP: I CONFREQ [ACKrcvd] id 7 len 16

*Mar 18 06:54:29.005: Vi5 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)

*Mar 18 06:54:29.005: Vi5 IPCP: Address 192.168.203.2 (0x0306C0A8CB02)

*Mar 18 06:54:29.005: Vi5 IPCP: O CONFACK [ACKrcvd] id 7 len 16

*Mar 18 06:54:29.005: Vi5 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)

*Mar 18 06:54:29.005: Vi5 IPCP: Address 192.168.203.2 (0x0306C0A8CB02)

*Mar 18 06:54:29.005: Se1/0:29 MLP: O ppp IPCP (8021) size 20 via oqueue

*Mar 18 06:54:29.005: Vi5 IPCP: State is Open

*Mar 18 06:54:29.005: Vi5 IPCP: Install route to 192.168.203.2

*Mar 18 06:54:29.005: Vi5 IPCP: Add link info for cef entry 192.168.203.2

*Mar 18 06:54:29.005: Vi5 DDR: dialer protocol up

*Mar 18 06:54:29.061: Se1/0:29 MLP: I ppp IP (0021) size 100

*Mar 18 06:54:29.809: Se1/0:29 MLP: I ppp IP (0021) size 100

*Mar 18 06:54:29.945: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial1/0:29, changed state to up

*Mar 18 06:54:29.953: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access5, changed state to up

*Mar 18 06:54:30.561: Se1/0:29 MLP: I ppp IP (0021) size 100

*Mar 18 06:54:36.981: Se1/0:29 MLP: I ppp IP (0021) size 82

*Mar 18 06:54:37.113: ISDN Se1/0:15 Q931: RX <- INFORMATION pd = 8 callref = 0x

804E

Display i = '1 UNITS'

*Mar 18 06:54:37.357: Se1/0:29 MLP: I ppp IP (0021) size 100

*Mar 18 06:54:38.449: Se1/0:29 MLP: O ppp IP (0021) size 64 via oqueue

*Mar 18 06:54:47.113: Se1/0:29 MLP: I ppp IP (0021) size 100

*Mar 18 06:54:59.065: Vi5: MLP: Load (1) above threshold, requesting another link

*Mar 18 06:55:01.925: Se1/0:29 MLP: I ppp IP (0021) size 52

*Mar 18 06:55:29.065: Vi5: MLP: Load (1) above threshold, requesting another link