Re: why LNS send CDN to LAC unexpected?

wminjuan · ‎05-02-2003

I have the debug l2x-packet output as following , why LNS send CDN message to LAC unexpected?

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 0, len 8, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Parse ICRQ

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 14, len 8, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Assigned Call ID 2

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 15, len 10, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Serial Number 2

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 18, len 10, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Bearer Type 3

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 25, len 10, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Phy Channel ID 21

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 21, len 11, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Called Number 17979

*May 3 12:35:50: Tnl 35370 L2TP: Parse AVP 22, len 13, flag 0x8000 (M)

*May 3 12:35:50: Tnl 35370 L2TP: Calling Number 3990400

*May 3 12:35:50: Tnl 35370 L2TP: No missing AVPs in ICRQ

*May 3 12:35:50: Tnl 35370 L2TP: I ICRQ, flg TLS, ver 2, len 82, tnl 35370, cl 0, ns 76, nr 110

C8 02 00 52 8A 2A 00 00 00 4C 00 6E 80 08 00 00

00 00 00 0A 80 08 00 00 00 0E 00 02 80 0A 00 00

00 0F 00 00 00 02 80 0A 00 00 00 12 00 00 00 ...

*May 3 12:35:50: Tnl 35370 L2TP: I ICRQ from as8010 tnl 1

*May 3 12:35:50: Tnl/Cl 35370/6972 L2TP: Session FS enabled

*May 3 12:35:50: Tnl/Cl 35370/6972 L2TP: Session state change from idle to wait-for-vaccess

*May 3 12:35:50: Tnl/Cl 35370/6972 L2TP: New session created

*May 3 12:35:50: Vi662 Tnl/Cl 35370/6963 L2TP: O CDN to as8010 1/3

*May 3 12:35:50: Vi662 Tnl/Cl 35370/6963 L2TP: O CDN, flg TLS, ver 2, len 38, tnl 1, cl 3, ns 0, nr 77

C8 02 00 26 00 01 00 03 00 00 00 4D 80 08 00 00

00 00 00 0E 80 08 00 00 00 0E 1B 33 80 0A 00 00

00 01 00 02 00 00

*May 3 12:35:50: Tnl 35370 L2TP: Control channel retransmit delay set to 1 seconds

*May 3 12:35:50: Vi662 Tnl/Cl 35370/6963 L2TP: Destroying session

*May 3 12:35:50: Vi662 Tnl/Cl 35370/6963 L2TP: Session state change from established to idle

*May 3 12:35:50: Vi662 Tnl/Cl 35370/6963 L2TP: Releasing idb for LAC/LNS tunnel 35370/1 session 6963 state idle

*May 3 12:35:50: %LINK-3-UPDOWN: Interface Virtual-Access662, changed state to down

zahmed · ‎05-02-2003

Lets find out whats going on behind the L2TP scene causing the LNS to generate CDN instead of ICRP . Lets capture the following in addition to l2x debug :

-debug ppp nego

-debug aaa authen

-debug aaa authoriz

If you have resource pooling enabled too, please include "debug resource-pool" also.

~Zulfi

wminjuan · ‎05-03-2003

please trace the "Tnl44857" and "Vi684" for all the debug message:

pr 30 15:49:55: L2TP: I SCCRQ from as8010 tnl 1

Apr 30 15:49:55: Tnl44857 L2TP: New tunnel created for remote as8010, address 61.147.35.42

Apr 30 15:49:55: Tnl44857 L2TP: O SCCRP to as8010 tnlid 1

Apr 30 15:49:55: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:49:55: Tnl44857 L2TP: Tunnel stateb change from idle to wait-ctl-reply

Apr 30 15:49:55: Tnl44857 L2TP: I SCCCN from as8010 tnl 1

Apr 30 15:49:55: Tnl44857 L2TP: Got a Challenge Response in SCCCN from as8010

Apr 30 15:49:55: Tnl44857 L2TP: Tunnel Authentication success

Apr 30 15:49:55: Tnl44857 L2TP: Tunnel state change from wait-ctl-reply to established

Apr 30 15:49:55: Tnl44857 L2TP: SM State established

Apr 30 15:49:55: Tnl44857 L2TP: I ICRQ from as8010 tnl 1

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: Session FS enabled

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: Session state change from idle to wait-for-vaccess

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: New session created

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: O ICRP to as8010 1/1

Apr 30 15:49:55: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: Session state change from wait-for-vaccess to wait-connect

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: I ICCN from as8010 tnl 1, cl 1

Apr 30 15:49:55: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:49:55: AAA/ACCT/EVENT/(00002194): CALL START

Apr 30 15:49:55: AAA/ACCT(00000000): add node, session 10153

Apr 30 15:49:55: AAA/ACCT/NET(00002194): add, count 1

Apr 30 15:49:55: AAA/ACCT/EVENT/(00002194): ATTR ADD

Apr 30 15:49:55: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:49:55: Vi684 PPP: Authorization NOT required

Apr 30 15:49:55: Vi684 PPP: Phase is ESTABLISHING

Apr 30 15:49:55: Vi684 Tnl/Sn44857/8561 L2TP: Session state change from wait-connect to established

Apr 30 15:49:55: Vi684 Tnl/Sn44857/8561 L2TP: O SLI to as8010 1/1

Apr 30 15:49:55: Vi684 Tnl/Sn44857/8561 L2TP: Sending send ACCM 0xFFFFFFFF and receive ACCM 0xFFFFFFFF

Apr 30 15:49:55: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:49:55: Vi684 PPP: Authorization NOT required

Apr 30 15:49:55: Vi684 LCP: O CONFREQ [Closed] id 175 len 24

Apr 30 15:49:55: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:49:55: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:49:55: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:49:55: Vi684 LCP: PFC (0x0702)

Apr 30 15:49:55: Vi684 LCP: ACFC (0x0802)

Apr 30 15:49:56: %LINK-3-UPDOWN: Interface Virtual-Access684, changed state to up

Apr 30 15:49:56: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access855, changed state to down

Apr 30 15:49:57: Tnl16137 L2TP: I Hello from as8010 tnl 1

Apr 30 15:49:57: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:49:57: Vi684 LCP: O CONFREQ [REQsent] id 176 len 24

Apr 30 15:49:57: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:49:57: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:49:57: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:49:57: Vi684 LCP: PFC (0x0702)

Apr 30 15:49:57: Vi684 LCP: ACFC (0x0802)

Apr 30 15:49:58: AAA/ACCT/NET(00002098): Pick method list 'default'

Apr 30 15:49:58: AAA/ACCT/SETMLIST(00002098): Handle FFFFFFFF, mlist 629B2A14, Name default

Apr 30 15:49:58: AAA/ACCT/EVENT/(00002098): NET DOWN

Apr 30 15:49:58: AAA/ACCT/NET(00002098): Queueing record is STOP osr 1

Apr 30 15:49:58: AAA/ACCT(00002098): del node, session 9805

Apr 30 15:49:58: AAA/ACCT/NET(00002098): free_rec, count 0

Apr 30 15:49:58: AAA/ACCT/NET(00002098): Setting session id 10154 : db=64170180

Apr 30 15:49:58: Vi454 PPP: Phase is TERMINATING

Apr 30 15:49:58: AAA/ACCT(00002098): Accouting method=radius (radius)

Apr 30 15:49:59: AAA/ACCT/NET(00002098): STOP protocol reply PASS

Apr 30 15:49:59: AAA/ACCT/NET(00002098): Cleaning up from Callback osr 0

Apr 30 15:49:59: AAA/ACCT/NET(00002098) Record not present

Apr 30 15:49:59: AAA/ACCT/NET(00002098) reccnt 0, csr FALSE, osr 0

Apr 30 15:49:59: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:49:59: Vi684 LCP: O CONFREQ [REQsent] id 177 len 24

Apr 30 15:49:59: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:49:59: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:49:59: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:49:59: Vi684 LCP: PFC (0x0702)

Apr 30 15:49:59: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:00: AAA/ACCT/EVENT/(00002098): CALL STOP

Apr 30 15:50:00: AAA/ACCT(00002098) reccnt 0, osr 0

Apr 30 15:50:00: %LINK-3-UPDOWN: Interface Virtual-Access454, changed state to down

Apr 30 15:50:01: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:01: Vi684 LCP: O CONFREQ [REQsent] id 178 len 24

Apr 30 15:50:01: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:01: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:01: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:01: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:01: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:03: AAA/ACCT/NET(00002022): Pick method list 'default'

Apr 30 15:50:03: AAA/ACCT/SETMLIST(00002022): Handle FFFFFFFF, mlist 629B2A14, Name default

Apr 30 15:50:03: AAA/ACCT/EVENT/(00002022): NET DOWN

Apr 30 15:50:03: AAA/ACCT/NET(00002022): Queueing record is STOP osr 1

Apr 30 15:50:03: AAA/ACCT(00002022): del node, session 9637

Apr 30 15:50:03: AAA/ACCT/NET(00002022): free_rec, count 0

Apr 30 15:50:03: AAA/ACCT/NET(00002022): Setting session id 10155 : db=643C06B8

Apr 30 15:50:03: AAA/ACCT(00002022): Accouting method=radius (radius)

Apr 30 15:50:03: AAA/ACCT/EVENT/(00002022): CALL STOP

Apr 30 15:50:03: AAA/ACCT(00002022) reccnt 0, osr 1

Apr 30 15:50:03: AAA/ACCT/NET(00002022): STOP protocol reply PASS

Apr 30 15:50:03: AAA/ACCT/NET(00002022): Cleaning up from Callback osr 0

Apr 30 15:50:03: AAA/ACCT/NET(00002022) Record not present

Apr 30 15:50:03: AAA/ACCT/NET(00002022) reccnt 0, csr TRUE, osr 0

Apr 30 15:50:03: AAA/ACCT/NET(00002022): Last rec in db, intf not enqueued

Apr 30 15:50:03: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:03: Vi684 LCP: O CONFREQ [REQsent] id 179 len 24

Apr 30 15:50:03: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:03: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:03: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:03: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:03: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:03: Vi237 LCP: echo_cnt 2, sent id 253, line up

Apr 30 15:50:04: Tnl43659 L2TP: I Hello from as8010 tnl 1

Apr 30 15:50:04: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access863, changed state to down

Apr 30 15:50:04: Tnl32637 L2TP: I Hello from as8010 tnl 1

Apr 30 15:50:04: Tnl13245 L2TP: I Hello from as8010 tnl 1

Apr 30 15:50:05: Tnl44857 L2TP: I ICRQ from as8010 tnl 1

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: Session FS enabled

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: Session state change from idle to wait-for-vaccess

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: New session created

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: O ICRP to as8010 1/2

Apr 30 15:50:05: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: Session state change from wait-for-vaccess to wait-connect

Apr 30 15:50:05: Tnl60895 L2TP: I Hello from as8010 tnl 1

Apr 30 15:50:05: Tnl/Sn44857/8562 L2TP: I ICCN from as8010 tnl 1, cl 2

Apr 30 15:50:05: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:50:05: AAA/ACCT/EVENT/(00002195): CALL START

Apr 30 15:50:05: AAA/ACCT(00000000): add node, session 10156

Apr 30 15:50:05: AAA/ACCT/NET(00002195): add, count 1

Apr 30 15:50:05: AAA/ACCT/EVENT/(00002195): ATTR ADD

Apr 30 15:50:05: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:50:05: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

wminjuan · ‎05-03-2003

continued:

Apr 30 15:50:05: AAA/ACCT/NET(000006A2): Pick method list 'default'

Apr 30 15:50:05: AAA/ACCT/SETMLIST(000006A2): Handle FFFFFFFF, mlist 629B2A14, Name default

Apr 30 15:50:05: AAA/ACCT/EVENT/(000006A2): NET DOWN

Apr 30 15:50:05: AAA/ACCT/NET(000006A2): Queueing record is STOP osr 1

Apr 30 15:50:05: AAA/ACCT(000006A2): del node, session 1893

Apr 30 15:50:05: AAA/ACCT/NET(000006A2): free_rec, count 0

Apr 30 15:50:05: AAA/ACCT/NET(000006A2): Setting session id 10157 : db=641488AC

Apr 30 15:50:05: AAA/ACCT(000006A2): Accouting method=radius (radius)

Apr 30 15:50:05: AAA/ACCT/NET(000020C7): Pick method list 'default'

Apr 30 15:50:05: AAA/ACCT/SETMLIST(000020C7): Handle FFFFFFFF, mlist 629B2A14, Name default

Apr 30 15:50:05: AAA/ACCT/EVENT/(000020C7): NET DOWN

Apr 30 15:50:05: AAA/ACCT/NET(000020C7): Queueing record is STOP osr 1

Apr 30 15:50:05: AAA/ACCT(000020C7): del node, session 9875

Apr 30 15:50:05: AAA/ACCT/NET(000020C7): free_rec, count 0

Apr 30 15:50:05: AAA/ACCT/NET(000020C7): Setting session id 10158 : db=643A1634

Apr 30 15:50:05: AAA/ACCT(000020C7): Accouting method=radius (radius)

Apr 30 15:50:05: AAA/ACCT/EVENT/(000020C7): CALL STOP

Apr 30 15:50:05: AAA/ACCT(000020C7) reccnt 0, osr 1

Apr 30 15:50:05: %LINK-3-UPDOWN: Interface Virtual-Access155, changed state to down

Apr 30 15:50:05: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:05: Vi684 LCP: O CONFREQ [REQsent] id 180 len 24

Apr 30 15:50:05: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:05: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:05: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:05: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:05: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:06: AAA/ACCT/NET(000006A2): STOP protocol reply PASS

Apr 30 15:50:06: AAA/ACCT/NET(000006A2): Cleaning up from Callback osr 0

Apr 30 15:50:06: AAA/ACCT/NET(000006A2) Record not present

Apr 30 15:50:06: AAA/ACCT/NET(000006A2) reccnt 0, csr FALSE, osr 0

Apr 30 15:50:06: AAA/ACCT/NET(000020C7): STOP protocol reply PASS

Apr 30 15:50:06: AAA/ACCT/NET(000020C7): Cleaning up from Callback osr 0

Apr 30 15:50:06: AAA/ACCT/NET(000020C7) Record not present

Apr 30 15:50:06: AAA/ACCT/NET(000020C7) reccnt 0, csr TRUE, osr 0

Apr 30 15:50:06: AAA/ACCT/NET(000020C7): Last rec in db, intf not enqueued

Apr 30 15:50:06: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access155, changed state to down

Apr 30 15:50:07: AAA/ACCT/EVENT/(000006A2): CALL STOP

Apr 30 15:50:07: AAA/ACCT(000006A2) reccnt 0, osr 0

Apr 30 15:50:08: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:08: Vi684 LCP: O CONFREQ [REQsent] id 181 len 24

Apr 30 15:50:08: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:08: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:08: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:08: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:08: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:08: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access283, changed state to down

Apr 30 15:50:10: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:10: Vi684 LCP: O CONFREQ [REQsent] id 182 len 24

Apr 30 15:50:10: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:10: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:10: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:10: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:10: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:12: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:12: Vi684 LCP: O CONFREQ [REQsent] id 183 len 24

Apr 30 15:50:12: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:12: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:12: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:12: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:12: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:14: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:14: Vi684 LCP: O CONFREQ [REQsent] id 184 len 24

Apr 30 15:50:14: Vi684 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:14: Vi684 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:14: Vi684 LCP: MagicNumber 0x0F5F3B7B (0x05060F5F3B7B)

Apr 30 15:50:14: Vi684 LCP: PFC (0x0702)

Apr 30 15:50:14: Vi684 LCP: ACFC (0x0802)

Apr 30 15:50:15: Tnl44857 L2TP: I ICRQ from as8010 tnl 1

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: Session FS enabled

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: Session state change from idle to wait-for-vaccess

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: New session created

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: O ICRP to as8010 1/3

Apr 30 15:50:15: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: Session state change from wait-for-vaccess to wait-connect

Apr 30 15:50:15: Tnl/Sn44857/8563 L2TP: I ICCN from as8010 tnl 1, cl 3

Apr 30 15:50:15: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:50:15: AAA/ACCT/EVENT/(00002196): CALL START

Apr 30 15:50:15: AAA/ACCT(00000000): add node, session 10159

Apr 30 15:50:15: AAA/ACCT/NET(00002196): add, count 1

Apr 30 15:50:15: AAA/ACCT/EVENT/(00002196): ATTR ADD

Apr 30 15:50:15: voice_parse_intf_name: Using the old NAS_PORT string

Apr 30 15:50:15: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:50:15: Vi459 PPP: Authorization NOT required

Apr 30 15:50:15: Vi459 LCP: O CONFREQ [Closed] id 45 len 24

Apr 30 15:50:15: Vi459 LCP: ACCM 0x000A0000 (0x0206000A0000)

Apr 30 15:50:15: Vi459 LCP: AuthProto PAP (0x0304C023)

Apr 30 15:50:15: Vi459 LCP: MagicNumber 0x0F5F8625 (0x05060F5F8625)

Apr 30 15:50:15: Vi459 LCP: PFC (0x0702)

Apr 30 15:50:15: Vi459 LCP: ACFC (0x0802)

Apr 30 15:50:15: %LINK-3-UPDOWN: Interface Virtual-Access459, changed state to up

Apr 30 15:50:16: Vi684 LCP: TIMEout: State REQsent

Apr 30 15:50:16: Vi684 Tnl/Sn44857/8561 L2TP: O CDN to as8010 1/1

Apr 30 15:50:16: Tnl44857 L2TP: Control channel retransmit delay set to 1 seconds

Apr 30 15:50:16: Vi684 Tnl/Sn44857/8561 L2TP: Destroying session

Apr 30 15:50:16: Vi684 Tnl/Sn44857/8561 L2TP: Session state change from established to idle

Apr 30 15:50:16: Vi684 Tnl/Sn44857/8561 L2TP: Releasing idb for LAC/LNS tunnel 44857/1 session 8561 state idle

Apr 30 15:50:16: Vi684 LCP: State is Listen

Apr 30 15:50:16: AAA/ACCT/EVENT/(00002194): CALL STOP

Apr 30 15:50:16: AAA/ACCT/CALL STOP(00002194): Sending stop requests

Apr 30 15:50:16: AAA/ACCT(00002194): Send all stops

Apr 30 15:50:16: AAA/ACCT/NET(00002194): STOP

Apr 30 15:50:16: AAA/ACCT/NET(00002194): Method list not found

Apr 30 15:50:16: AAA/ACCT(00002194): del node, session 10153

Apr 30 15:50:16: AAA/ACCT/NET(00002194): free_rec, count 0

Apr 30 15:50:16: AAA/ACCT/NET(00002194) reccnt 0, csr TRUE, osr 0

Apr 30 15:50:16: AAA/ACCT/NET(00002194): Last rec in db, intf not enqueued

Apr 30 15:50:16: %LINK-3-UPDOWN: Interface Virtual-Access684, changed state to down

Apr 30 15:50:16: AAA/ACCT/EVENT/(00002194): NET DOWN

Apr 30 15:50:16: Vi684 LCP: State is Closed

Apr 30 15:50:16: Vi684 PPP: Phase is DOWN

makchitale · ‎05-03-2003

We see LNS & LAC seem to establish a tunnel & bring up the session where ICCN come in from LAC. Now we do not see the client (router/ PC) that's initiating the L2TP session respond to the LCP sent out by the LNS & the session eventually times out.

Below I have picked key debug outputs only:

Apr 30 15:49:55: L2TP: I SCCRQ from as8010 tnl 1

Apr 30 15:49:55: Tnl44857 L2TP: O SCCRP to as8010 tnlid 1

Apr 30 15:49:55: Tnl44857 L2TP: I SCCCN from as8010 tnl 1

Apr 30 15:49:55: Tnl44857 L2TP: Got a Challenge Response in SCCCN from as8010

Apr 30 15:49:55: Tnl44857 L2TP: Tunnel Authentication success

**Tunnel comes up fine (above)***

**Session setup starts (below)***

Apr 30 15:49:55: Tnl44857 L2TP: I ICRQ from as8010 tnl 1

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: O ICRP to as8010 1/1

Apr 30 15:49:55: Tnl/Sn44857/8561 L2TP: I ICCN from as8010 tnl 1, cl 1

***LNS is cloning a VAccess interface & starts LCP***

Apr 30 15:49:56: %LINK-3-UPDOWN: Interface Virtual-Access684, changed state to up

Apr 30 15:49:55: Vi684 LCP: O CONFREQ [Closed] id 175 len 24

----send out every 2 seconds:----

Apr 30 15:50:03: Vi684 LCP: O CONFREQ [REQsent] id 179 len 24

The LNS does not see any response come in for it's LCP OUT & eventually times out.

Apr 30 15:50:16: Vi684 Tnl/Sn44857/8561 L2TP: Releasing idb for LAC/LNS tunnel 44857/1 session 8561 state idle

1)Ideally the LAC will force the LCP that it negotiates with the client onto the LNS....maybe you have "lcp renego always / on-mismatch" under the vpdn-group.

What platform is the LAC? Cisco or non-Cisco?

2)What is the client? A router calling in or a PC.....it will be interesting to see the ppp debugs on it to see whether it sees/ responds to the LCP requests from the LNS.

3)Is this issue seen with only this particular client or will all?

4)Will be interesting to see the running config from the LAC/ LNS / client (if it's a router calling) along the following debugs on LAN & LNS:

sh run / sh ver

deb vpdn eve / deb vpdn l2x-eve / deb vpdn l2x-err / deb vtemp / deb ppp nego

Thanks, Mak.

makchitale · ‎05-03-2003

These links might be useful:

http://www.cisco.com/warp/public/471/vpdn_20980.html

http://www.cisco.com/warp/public/116/l2tp_3886.html

http://www.cisco.com/warp/public/471/l2tp-win2k-cit.html

Thanks, Mak.

wminjuan · ‎05-03-2003

1) I have lcp renego always under the vpdn-group ON LNS. LACs are non-cisco access servers.

2) the clients is PCs

3) this problem is strange because it is associated with all the clients for a while , and it will be ok for another time.

4) I have put debug vpdn events/debug vpdn l2x-events on the first message. and debug ppp nego as following messages. please refer last 3 three messages I put on. When I try to open all the debug you list. the LNS run high CPU utility. then it crashed.

BTW can you help me decoding this CDN AVP?

Apr 30 15:11:23: Vi791 Tnl/Sn62161/8182 L2TP: O CDN, flg TLS, ver 2, len 38, tnl 1, cl 1, ns 0, nr 14

C8 02 00 26 00 01 00 01 00 00 00 0E 80 08 00 00

00 00 00 0E 80 08 00 00 00 0E 1F F6 80 0A 00 00

00 01 00 02 00 00

zahmed · ‎05-04-2003

Could you try "lcp renego on-mismatch" instead of always ? Also take a look at "show interface virtual-access x" after CDN has gone out from LNC to see if there are any input errors. We need to find out why we do not see incoming LCPs at all.

~Zulfi

wminjuan · ‎05-04-2003

I have tried "lcp renego on-mismatch" , and following is " show interface virtual-access x" output :

Router#sh int virtual-access 994

Virtual-Access994 is down, line protocol is down

Hardware is Virtual Access interface

Interface is unnumbered. Using address of Ethernet0/0 (61.155.4.113)

MTU 1492 bytes, BW 64 Kbit, DLY 100000 usec,

reliability 255/255, txload 1/255, rxload 1/255

Encapsulation PPP, loopback not set

DTR is pulsed for 5 seconds on reset

LCP Closed

Closed: LEXCP, BRIDGECP, IPCP, CCP, CDPCP, LLC2, BACP, IPV6CP

Last input never, output never, output hang never

Last clearing of "show interface" counters 00:00:29

Queueing strategy: fifo

Output queue 0/40, 0 drops; input queue 0/75, 0 drops

5 minute input rate 0 bits/sec, 0 packets/sec

5 minute output rate 0 bits/sec, 0 packets/sec

0 packets input, 0 bytes, 0 no buffer

Received 0 broadcasts, 0 runts, 0 giants, 0 throttles

0 input errors, 0 CRC, 0 frame, 0 overrun, 0 ignored, 0 abort

0 packets output, 0 bytes, 0 underruns

0 output errors, 0 collisions, 0 interface resets

0 output buffer failures, 0 output buffers swapped out

0 carrier transitions

zahmed · ‎05-05-2003

Last clearing of show interface counters line tends me to believe that you did clear counters for some reason and thats why its not showing outbound packets either. Anyway, I would suggest you to open up a TAC case on this one.

~Zulfi

wminjuan · ‎05-06-2003

ok, I will open a case for it.