
Сообщение от
denisfaq
хм, а что за роутер, на какой прошивке?
Прошивка OpenWrt. По идее надо включить debug для pppd и посмотреть на каком этапе зависает сессия. Но проверить сейчас не могу, ибо это же не мое хозяйство, а вламываться сейчас на роутер и начинать эксперименты без спросу, как-то не очень красиво.
В принципе проблема решена, хоть и через жопу. Остальное это головняк ТТК. Если им на своих абонентов похуй, то пусть дальше авторизуют через раз. Ладно когда человек соображает, что к чему, и знает как выкрутиться из ситуации запихав в крон всякие выкрутасы. А обычный человек столкнувшись с такой проблемой просто назовет провайдера мудаком и уйдет к другому провайдеру у которого PPPoE-сессии поднимаются с первого раза. 
---------- Добавлено 06.10.2012 в 18:19 ----------
Договорился насчет потестировать с несчастным абонентом ТТК.
Вот что происходит с опцией debug:
Код:
Oct 6 09:00:00 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:00 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 17 f3] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:01 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:01 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:01 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 17 98] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:03 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADR session 0x0 length 65
Oct 6 09:00:03 openwrt daemon.debug pppd[856]: dst 0:15:17:8e:d5:4c src 1c:af:f7:c8:18:bc
Oct 6 09:00:03 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 10 00 b6 e0] [AC-cookie c0 b0 50 c7] [vendor-specific 00 00 0d e9 01 21 31 43 3a 41 46 3a 46 37 3a 43 38 3a 31 38 3a 42 43 3a 3a 31 37 32 2e 31 36 2e... (length 41)]
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 22 e0] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 57
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:d3:19:19
Oct 6 09:00:04 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 42 03 00 00] [vendor-specific 00 00 0d e9 01 21 31 43 3a 37 45 3a 45 35 3a 44 33 3a 31 39 3a 31 39 3a 3a 31 37 32 2e 31 36 2e... (length 41)]
Oct 6 09:00:05 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:05 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:05 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 18 37] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 22 ad] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 0:1f:d0:59:f5:6b
Oct 6 09:00:06 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 3a c2] [vendor-specific 00 00 0d e9 01 22 30 30 3a 31 46 3a 44 30 3a 35 39 3a 46 35 3a 36 42 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADR session 0x0 length 69
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: dst 0:1b:21:d7:4b:21 src 1c:7e:e5:e1:48:2f
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: [service-name TTK] [host-uniq 09 03 00 00] [AC-cookie c0 39 2d c6] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 45 31 3a 34 38 3a 32 46 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:07 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 23 1a] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:09 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADR session 0x0 length 65
Oct 6 09:00:09 openwrt daemon.debug pppd[856]: dst 0:15:17:8e:d5:4c src 1c:af:f7:c8:18:bc
Oct 6 09:00:09 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 10 00 b6 e0] [AC-cookie c0 b0 50 c7] [vendor-specific 00 00 0d e9 01 21 31 43 3a 41 46 3a 46 37 3a 43 38 3a 31 38 3a 42 43 3a 3a 31 37 32 2e 31 36 2e... (length 41)]
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 18 37] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:10 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 17 f3] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:11 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 59
Oct 6 09:00:11 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 0:14:bf:91:63:11
Oct 6 09:00:11 openwrt daemon.debug pppd[856]: [host-uniq 78 d3 00 10] [service-name] [vendor-specific 00 00 0d e9 01 23 30 30 3a 31 34 3a 42 46 3a 39 31 3a 36 33 3a 31 31 3a 3a 31 37 32 2e 31 36 2e... (length 43)]
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADR session 0x0 length 69
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: dst 0:1b:21:d7:4b:21 src 1c:7e:e5:e1:48:2f
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: [service-name TTK] [host-uniq 09 03 00 00] [AC-cookie c0 39 2d c6] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 45 31 3a 34 38 3a 32 46 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADR session 0x0 length 73
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: dst 0:15:17:8e:d2:8e src 1c:7e:e5:e5:f1:a3
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: [service-name M-PM-"M-PM-"M-PM-^Z] [host-uniq 5b 03 00 00] [AC-cookie 00 3d 7e c6] [vendor-specific 00 00 0d e9 01 23 31 43 3a 37 45 3a 45 35 3a 45 35 3a 46 31 3a 41 33 3a 3a 31 37 32 2e 31 36 2e... (length 43)]
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:12 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 23 1a] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:14 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:14 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:14 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 22 e0] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 1c:7e:e5:3e:be:97
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 18 73] [vendor-specific 00 00 0d e9 01 22 31 43 3a 37 45 3a 45 35 3a 33 45 3a 42 45 3a 39 37 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: Recv PPPOE Discovery V1T1 PADI session 0x0 length 58
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: dst ff:ff:ff:ff:ff:ff src 84:c9:b2:64:69:23
Oct 6 09:00:15 openwrt daemon.debug pppd[856]: [service-name] [host-uniq 00 00 23 4d] [vendor-specific 00 00 0d e9 01 22 38 34 3a 43 39 3a 42 32 3a 36 34 3a 36 39 3a 32 33 3a 3a 31 37 32 2e 31 36 2e... (length 42)]
Oct 6 09:00:16 openwrt daemon.notice netifd: Interface 'wan' is now down
Oct 6 09:00:21 openwrt daemon.info pppd[1840]: Plugin rp-pppoe.so loaded.
Oct 6 09:00:21 openwrt daemon.info pppd[1840]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: pppd 2.4.5 started by root, uid 0
Oct 6 09:00:21 openwrt daemon.err pppd[1840]: Interface eth0.2 has MTU of 1400 -- should be at least 1500.
Oct 6 09:00:21 openwrt daemon.err pppd[1840]: This may cause serious connection problems.
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: dst ff:ff:ff:ff:ff:ff src b0:48:7a:e8:11:9c
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: [service-name] [host-uniq 00 00 07 30]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 47
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: dst b0:48:7a:e8:11:9c src cc:ef:48:79:1d:30
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: [service-name] [host-uniq 00 00 07 30] [AC-name Bras-ASR-01] [AC-cookie 91 bd ea 65 48 68 ac c5 70 43 16 b8 66 a5 4d f9]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: dst cc:ef:48:79:1d:30 src b0:48:7a:e8:11:9c
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: [service-name] [host-uniq 00 00 07 30] [AC-cookie 91 bd ea 65 48 68 ac c5 70 43 16 b8 66 a5 4d f9]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: Recv PPPOE Discovery V1T1 PADS session 0xe02b length 32
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: dst b0:48:7a:e8:11:9c src cc:ef:48:79:1d:30
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: [service-name] [host-uniq 00 00 07 30] [AC-cookie 91 bd ea 65 48 68 ac c5 70 43 16 b8 66 a5 4d f9]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: PADS: Service-Name: ''
Oct 6 09:00:21 openwrt daemon.info pppd[1840]: PPP session is 57387
Oct 6 09:00:21 openwrt daemon.warn pppd[1840]: Connected to cc:ef:48:79:1d:30 via interface eth0.2
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: using channel 1
Oct 6 09:00:21 openwrt daemon.info pppd[1840]: Using interface pppoe-wan
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: Connect: pppoe-wan <--> eth0.2
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [LCP ConfReq id=0x1 <mru 1400> <magic 0xb340084e>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [LCP ConfReq id=0x1 <mru 1492> <auth chap MD5> <magic 0xff018419>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [LCP ConfAck id=0x1 <mru 1492> <auth chap MD5> <magic 0xff018419>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [LCP ConfNak id=0x1 <mru 1492>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [LCP ConfReq id=0x2 <mru 1492> <magic 0xb340084e>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [LCP ConfAck id=0x2 <mru 1492> <magic 0xb340084e>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [LCP EchoReq id=0x0 magic=0xb340084e]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [LCP EchoRep id=0x0 magic=0xff018419]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [CHAP Challenge id=0x1 <7e04295dfe8bbe8f9ccc83e17e065763>, name = "Bras-ASR-01"]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [CHAP Response id=0x1 <a4f4989817b43008a5d3fe223d98d997>, name = "38100****"]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [CHAP Success id=0x1 ""]
Oct 6 09:00:21 openwrt daemon.info pppd[1840]: CHAP authentication succeeded
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: CHAP authentication succeeded
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: peer from calling number CC:EF:48:79:1D:30 authorized
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [IPCP ConfReq id=0x1 <addr 164.215.80.10>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [IPCP ConfAck id=0x1 <addr 164.215.80.10>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [IPCP ConfNak id=0x1 <addr 188.244.149.7> <ms-dns1 193.227.98.12> <ms-dns2 188.168.31.10>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: sent [IPCP ConfReq id=0x2 <addr 188.244.149.7> <ms-dns1 193.227.98.12> <ms-dns2 188.168.31.10>]
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: rcvd [IPCP ConfAck id=0x2 <addr 188.244.149.7> <ms-dns1 193.227.98.12> <ms-dns2 188.168.31.10>]
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: local IP address 188.244.149.7
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: remote IP address 164.215.80.10
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: primary DNS address 193.227.98.12
Oct 6 09:00:21 openwrt daemon.notice pppd[1840]: secondary DNS address 188.168.31.10
Oct 6 09:00:21 openwrt daemon.debug pppd[1840]: Script /lib/netifd/ppp-up started (pid 1849)
Oct 6 09:00:22 openwrt daemon.notice netifd: Interface 'wan' is now up
Oct 6 09:00:22 openwrt daemon.debug pppd[1840]: Script /lib/netifd/ppp-up finished (pid 1849), status = 0x1
Oct 6 09:00:22 openwrt user.notice ifup: Enabling Router Solicitations on wan (pppoe-wan)
Oct 6 09:00:23 openwrt user.info firewall: adding wan (pppoe-wan) to zone wan
Oct 6 09:00:24 openwrt daemon.info dnsmasq[1730]: reading /tmp/resolv.conf.auto
Oct 6 09:00:24 openwrt daemon.info dnsmasq[1730]: using nameserver 193.227.98.12#53
Oct 6 09:00:24 openwrt daemon.info dnsmasq[1730]: using nameserver 188.168.31.10#53
Oct 6 09:00:24 openwrt daemon.info dnsmasq[1730]: using local addresses only for domain lan
Время UTC, то есть по нашему было это в 18:00. Роутер был перегружен где-то без пяти шесть вечера. Как видим pppd целых пять минут страдает какой-то херней в бесконечном цикле, а потом в 09:00:16 крон его перезапускает после чего все отлично соединяется. К сожалению у OpenWrt небольшой буфер для лога, и с чего все начинается не видно.