Вырезки дебагов 2-х неудачных подключений
============================================
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19504: *Jun 26 09:23:48.975: ppp98 PPP: Send Message[Dynamic Bind Response]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19505: *Jun 26 09:23:48.975: ppp98 PPP: Using default call direction
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19506: *Jun 26 09:23:48.975: ppp98 PPP: Treating connection as a dedicated line
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19507: *Jun 26 09:23:48.975: ppp98 PPP: Session handle[4C0000E3] Session id[98]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19508: *Jun 26 09:23:48.975: ppp98 PPP: Phase is ESTABLISHING, Active Open
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19509: *Jun 26 09:23:48.975: ppp98 LCP: O CONFREQ [Closed] id 1 len 18
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19510: *Jun 26 09:23:48.975: ppp98 LCP: MRU 1492 (0x010405D4)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19511: *Jun 26 09:23:48.975: ppp98 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19512: *Jun 26 09:23:48.975: ppp98 LCP: MagicNumber 0x16F736C2 (0x050616F736C2)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19513: *Jun 26 09:23:48.995: ppp98 LCP: I CONFREQ [REQsent] id 0 len 13
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19514: *Jun 26 09:23:48.995: ppp98 LCP: MagicNumber 0x2FAD0262 (0x05062FAD0262)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19515: *Jun 26 09:23:48.995: ppp98 LCP: Callback 6 (0x0D0306)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19516: *Jun 26 09:23:48.995: ppp98 LCP: O CONFREJ [REQsent] id 0 len 7
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19517: *Jun 26 09:23:48.995: ppp98 LCP: Callback 6 (0x0D0306)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19518: *Jun 26 09:23:48.995: ppp98 LCP: I CONFNAK [REQsent] id 1 len 8
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19519: *Jun 26 09:23:48.995: ppp98 LCP: MRU 1492 (0x010405D4)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19520: *Jun 26 09:23:48.995: ppp98 LCP: O CONFREQ [REQsent] id 2 len 14
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19521: *Jun 26 09:23:48.995: ppp98 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19522: *Jun 26 09:23:48.995: ppp98 LCP: MagicNumber 0x16F736C2 (0x050616F736C2)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19523: *Jun 26 09:23:48.995: ppp98 LCP: I CONFREQ [REQsent] id 1 len 10
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19524: *Jun 26 09:23:48.995: ppp98 LCP: MagicNumber 0x2FAD0262 (0x05062FAD0262)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19525: *Jun 26 09:23:48.995: ppp98 LCP: O CONFACK [REQsent] id 1 len 10
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19526: *Jun 26 09:23:48.995: ppp98 LCP: MagicNumber 0x2FAD0262 (0x05062FAD0262)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19527: *Jun 26 09:23:48.995: ppp98 LCP: I CONFACK [ACKsent] id 2 len 14
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19528: *Jun 26 09:23:48.999: ppp98 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19529: *Jun 26 09:23:48.999: ppp98 LCP: MagicNumber 0x16F736C2 (0x050616F736C2)
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19530: *Jun 26 09:23:48.999: ppp98 LCP: State is Open
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19531: *Jun 26 09:23:48.999: ppp98 PPP: Phase is AUTHENTICATING, by this end
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19532: *Jun 26 09:23:48.999: ppp98 LCP: I IDENTIFY [Open] id 2 len 18 magic 0x2FAD0262 MSRASV5.00
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19533: *Jun 26 09:23:48.999: ppp98 LCP: I IDENTIFY [Open] id 3 len 23 magic 0x2FAD0262 MSRAS-1-TEMPL02
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19534: *Jun 26 09:23:48.999: ppp98 PAP: I AUTH-REQ id 155 len 19 from "xxxxx"
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19535: *Jun 26 09:23:48.999: ppp98 PAP: Authenticating peer xxxxx
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19536: *Jun 26 09:23:48.999: ppp98 PPP: Phase is FORWARDING, Attempting Forward
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19537: *Jun 26 09:23:48.999: ppp98 PPP SSS: Receive SSS-Mgr Connect-Local
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19538: *Jun 26 09:23:48.999: ppp98 PPP: Phase is AUTHENTICATING, Unauthenticated User
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19539: *Jun 26 09:23:48.999: RADIUS/ENCODE(00000066):Orig. component type = PPoE
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19540: *Jun 26 09:23:48.999: RADIUS(00000066): Config NAS IP: 192.168.x.12
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19541: *Jun 26 09:23:49.015: RADIUS: Received from id 1645/99 192.168.x.102:1645, Access-Accept, len 114
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19542: *Jun 26 09:23:49.015: ppp98 PPP: Phase is FORWARDING, Attempting Forward
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19543: *Jun 26 09:23:49.015: ppp98 PPP: Send Message[Connect Local]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19544: *Jun 26 09:23:49.027: Vi37 PPP: Phase is DOWN, Setup
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19545: *Jun 26 09:23:49.027: Vi37 PPP: Attempt to free context twice
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19546: *Jun 26 09:23:49.027: -Traceback= 0x61FC11CC 0x61FE486C 0x62614F34 0x62615094
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19547: *Jun 26 09:23:49.027: ppp98 PPP: Bind to [Virtual-Access37]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19548: *Jun 26 09:23:49.027: Vi37 PPP: Send Message[Static Bind Response]
2007-06-26 14:26:04 Local7.Error 192.168.x.12 %LINK-3-UPDOWN: Interface Virtual-Access37, changed state to up
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19550: *Jun 26 09:23:49.031: Vi37 PPP: Phase is AUTHENTICATING, Authenticated User
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19551: *Jun 26 09:23:49.031: Vi37 PAP: O AUTH-ACK id 155 len 5
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19552: *Jun 26 09:23:49.031: Vi37 PPP: Phase is FORWARDING
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19553: *Jun 26 09:23:49.035: Vi37 PPP: Queue CCP code[1] id[4]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19554: *Jun 26 09:23:49.035: Vi37 PPP: Queue IPCP code[1] id[5]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19555: *Jun 26 09:23:49.035: Vi37 PPP: Sending Acct Event[Down] id[66]
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19556: *Jun 26 09:23:49.035: Vi37 PPP: Phase is TERMINATING
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19557: *Jun 26 09:23:49.035: Vi37 LCP: O TERMREQ [Open] id 3 len 4
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19558: *Jun 26 09:23:49.035: Vi37 LCP: I TERMACK [TERMsent] id 3 len 4
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19559: *Jun 26 09:23:49.035: Vi37 LCP: State is Closed
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19560: *Jun 26 09:23:49.035: Vi37 PPP: Phase is DOWN
2007-06-26 14:26:04 Local7.Debug 192.168.x.12 19561: *Jun 26 09:23:49.035: Vi37 PPP: Send Message[Disconnect]
2007-06-26 14:26:05 Local7.Error 192.168.x.12 %LINK-3-UPDOWN: Interface Virtual-Access37, changed state to down
2007-06-26 14:26:09 Local7.Debug 192.168.x.12 19563: *Jun 26 09:23:53.075: RADIUS/ENCODE(0000001B):Orig. component type = PPoE
2007-06-26 14:26:09 Local7.Debug 192.168.x.12 19564: *Jun 26 09:23:53.075: RADIUS/ENCODE(0000001B): Acct-session-id pre-pended with Nas Port = 0/0/1/151
2007-06-26 14:26:09 Local7.Debug 192.168.x.12 19565: *Jun 26 09:23:53.075: RADIUS(0000001B): Config NAS IP: 192.168.x.12
2007-06-26 14:26:09 Local7.Debug 192.168.x.12 19566: *Jun 26 09:23:53.091: RADIUS: Received from id 1646/170 192.168.x.102:1646, Accounting-response, len 20
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19567: *Jun 26 09:23:55.415: ppp99 PPP: Send Message[Dynamic Bind Response]
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19568: *Jun 26 09:23:55.415: ppp99 PPP: Using default call direction
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19569: *Jun 26 09:23:55.415: ppp99 PPP: Treating connection as a dedicated line
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19570: *Jun 26 09:23:55.415: ppp99 PPP: Session handle[830000E5] Session id[99]
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19571: *Jun 26 09:23:55.415: ppp99 PPP: Phase is ESTABLISHING, Active Open
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19572: *Jun 26 09:23:55.419: ppp99 LCP: O CONFREQ [Closed] id 1 len 18
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19573: *Jun 26 09:23:55.419: ppp99 LCP: MRU 1492 (0x010405D4)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19574: *Jun 26 09:23:55.419: ppp99 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19575: *Jun 26 09:23:55.419: ppp99 LCP: MagicNumber 0x16F74FEC (0x050616F74FEC)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19576: *Jun 26 09:23:55.435: ppp99 LCP: I CONFREQ [REQsent] id 0 len 13
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19577: *Jun 26 09:23:55.435: ppp99 LCP: MagicNumber 0x0198443C (0x05060198443C)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19578: *Jun 26 09:23:55.435: ppp99 LCP: Callback 6 (0x0D0306)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19579: *Jun 26 09:23:55.435: ppp99 LCP: O CONFREJ [REQsent] id 0 len 7
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19580: *Jun 26 09:23:55.435: ppp99 LCP: Callback 6 (0x0D0306)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19581: *Jun 26 09:23:55.435: ppp99 LCP: I CONFNAK [REQsent] id 1 len 8
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19582: *Jun 26 09:23:55.435: ppp99 LCP: MRU 1492 (0x010405D4)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19583: *Jun 26 09:23:55.435: ppp99 LCP: O CONFREQ [REQsent] id 2 len 14
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19584: *Jun 26 09:23:55.435: ppp99 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19585: *Jun 26 09:23:55.435: ppp99 LCP: MagicNumber 0x16F74FEC (0x050616F74FEC)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19586: *Jun 26 09:23:55.435: ppp99 LCP: I CONFREQ [REQsent] id 1 len 10
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19587: *Jun 26 09:23:55.435: ppp99 LCP: MagicNumber 0x0198443C (0x05060198443C)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19588: *Jun 26 09:23:55.435: ppp99 LCP: O CONFACK [REQsent] id 1 len 10
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19589: *Jun 26 09:23:55.435: ppp99 LCP: MagicNumber 0x0198443C (0x05060198443C)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19590: *Jun 26 09:23:55.439: ppp99 LCP: I CONFACK [ACKsent] id 2 len 14
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19591: *Jun 26 09:23:55.439: ppp99 LCP: AuthProto PAP (0x0304C023)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19592: *Jun 26 09:23:55.439: ppp99 LCP: MagicNumber 0x16F74FEC (0x050616F74FEC)
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19593: *Jun 26 09:23:55.439: ppp99 LCP: State is Open
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19594: *Jun 26 09:23:55.439: ppp99 PPP: Phase is AUTHENTICATING, by this end
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19595: *Jun 26 09:23:55.439: ppp99 LCP: I IDENTIFY [Open] id 2 len 18 magic 0x0198443C MSRASV5.00
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19596: *Jun 26 09:23:55.439: ppp99 LCP: I IDENTIFY [Open] id 3 len 23 magic 0x0198443C MSRAS-1-TEMPL02
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19597: *Jun 26 09:23:55.439: ppp99 PAP: I AUTH-REQ id 156 len 19 from "xxxxx"
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19598: *Jun 26 09:23:55.439: ppp99 PAP: Authenticating peer xxxxx
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19599: *Jun 26 09:23:55.439: ppp99 PPP: Phase is FORWARDING, Attempting Forward
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19600: *Jun 26 09:23:55.439: ppp99 PPP SSS: Receive SSS-Mgr Connect-Local
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19601: *Jun 26 09:23:55.439: ppp99 PPP: Phase is AUTHENTICATING, Unauthenticated User
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19602: *Jun 26 09:23:55.439: RADIUS/ENCODE(00000067):Orig. component type = PPoE
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19603: *Jun 26 09:23:55.439: RADIUS(00000067): Config NAS IP: 192.168.x.12
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19604: *Jun 26 09:23:55.455: RADIUS: Received from id 1645/100 192.168.x.102:1645, Access-Accept, len 114
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19605: *Jun 26 09:23:55.455: ppp99 PPP: Phase is FORWARDING, Attempting Forward
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19606: *Jun 26 09:23:55.455: ppp99 PPP: Send Message[Connect Local]
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19607: *Jun 26 09:23:55.455: Vi36 PPP: Phase is DOWN, Setup
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19608: *Jun 26 09:23:55.459: Vi36 PPP: Attempt to free context twice
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19609: *Jun 26 09:23:55.459: -Traceback= 0x61FC11CC 0x61FE486C 0x62614F34 0x62615094
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19610: *Jun 26 09:23:55.459: ppp99 PPP: Bind to [Virtual-Access36]
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19611: *Jun 26 09:23:55.459: Vi36 PPP: Send Message[Static Bind Response]
2007-06-26 14:26:10 Local7.Error 192.168.x.12 %LINK-3-UPDOWN: Interface Virtual-Access36, changed state to up
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19613: *Jun 26 09:23:55.463: Vi36 PPP: Phase is AUTHENTICATING, Authenticated User
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19614: *Jun 26 09:23:55.463: Vi36 PAP: O AUTH-ACK id 156 len 5
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19615: *Jun 26 09:23:55.463: Vi36 PPP: Phase is FORWARDING
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19616: *Jun 26 09:23:55.463: Vi36 PPP: Sending Acct Event[Down] id[67]
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19617: *Jun 26 09:23:55.463: Vi36 PPP: Phase is TERMINATING
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19618: *Jun 26 09:23:55.463: Vi36 LCP: O TERMREQ [Open] id 3 len 4
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19619: *Jun 26 09:23:55.467: Vi36 CCP: LCP not open, discarding packet
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19620: *Jun 26 09:23:55.467: Vi36 IPCP: LCP not open, discarding packet
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19621: *Jun 26 09:23:55.467: Vi36 LCP: I TERMACK [TERMsent] id 3 len 4
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19622: *Jun 26 09:23:55.467: Vi36 LCP: State is Closed
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19623: *Jun 26 09:23:55.467: Vi36 PPP: Phase is DOWN
2007-06-26 14:26:10 Local7.Debug 192.168.x.12 19624: *Jun 26 09:23:55.467: Vi36 PPP: Send Message[Disconnect]
2007-06-26 14:26:11 Local7.Error 192.168.x.12 %LINK-3-UPDOWN: Interface Virtual-Access36, changed state to down
2007-06-26 14:26:41 Local7.Debug 192.168.x.12 19626: *Jun 26 09:24:25.119: RADIUS/ENCODE(00000016):Orig. component type = PPoE
2007-06-26 14:26:41 Local7.Debug 192.168.x.12 19627: *Jun 26 09:24:25.119: RADIUS/ENCODE(00000016): Acct-session-id pre-pended with Nas Port = 0/0/1/4
2007-06-26 14:26:41 Local7.Debug 192.168.x.12 19628: *Jun 26 09:24:25.119: RADIUS(00000016): Config NAS IP: 192.168.x.12
2007-06-26 14:26:41 Local7.Debug 192.168.x.12 19629: *Jun 26 09:24:25.135: RADIUS: Received from id 1646/171 192.168.x.102:1646, Accounting-response, len 20
2007-06-26 14:26:47 Local7.Debug 192.168.x.12 19630: *Jun 26 09:24:31.607: RADIUS/ENCODE(0000001D):Orig. component type = PPoE
2007-06-26 14:26:47 Local7.Debug 192.168.x.12 19631: *Jun 26 09:24:31.607: RADIUS/ENCODE(0000001D): Acct-session-id pre-pended with Nas Port = 0/0/1/83
2007-06-26 14:26:47 Local7.Debug 192.168.x.12 19632: *Jun 26 09:24:31.607: RADIUS(0000001D): Config NAS IP: 192.168.x.12
2007-06-26 14:26:47 Local7.Debug 192.168.x.12 19633: *Jun 26 09:24:31.623: RADIUS: Received from
|
