purestg2

yKpon · 2013-03-14 11:14:54

поймал

skyprox:~# ifconfig | grep vpn_himik

пусто

в stg статус online

в syslog никаких попыток авторизаций от pppd

в stargazer.log тоже

как только пустил роутер абонента в перезагрузку в stg online пропал, в логах всё корректно завершилось, и удачно авторизовалось

такое ощущение что stg+purestg2 оценивал что всё хорошо, и абонент авторизован несмотря на то что туннеля не было

в поле IP у меня сейчас 2 адреса, это IP-туннеля и IP-локальный, может stg слышит любой из адресов (в данном случае локальный) и думает всё OK, не?

процесс есть, туннеля нет! может это как то связано с переименованием туннеля?

skyprox:~# cat /var/log/syslog | grep pppd | grep 4587
Mar 14 14:59:59 skyprox pppd[4587]: Plugin purestg2.so loaded.
Mar 14 14:59:59 skyprox pppd[4587]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 14 14:59:59 skyprox pppd[4587]: purestg2: Chap check is allowed.
Mar 14 14:59:59 skyprox pppd[4587]: pppd 2.4.5 started by root, uid 0
Mar 14 14:59:59 skyprox pppd[4587]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 14 14:59:59 skyprox pppd[4587]: purestg2: ifunit set to 20.
Mar 14 14:59:59 skyprox pppd[4587]: Using interface ppp20
Mar 14 14:59:59 skyprox pppd[4587]: Connect: ppp20 <--> /dev/pts/10
Mar 14 15:00:00 skyprox pppd[4587]: purestg2: Chap check is allowed.
Mar 14 15:00:00 skyprox pppd[4587]: purestg2: Chap check is allowed.
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: CHAP started.
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: Got passwd for user himik.
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: IP choose started.
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: Allowed address.
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: Good address.
Mar 14 15:00:02 skyprox pppd[4587]: local  IP address 10.0.0.253
Mar 14 15:00:02 skyprox pppd[4587]: remote IP address 10.168.5.4
Mar 14 15:00:02 skyprox pppd[4587]: purestg2: User himik connected.
skyprox:~# ifconfig vpn_himik
vpn_himik: error fetching interface information: Device not found
skyprox:~# ps ax | grep pppd | grep 4587
 4587 ?        Ssl    0:00 pppd pty /usr/sbin/pppoe -n -I eth_vlan51 -e 34:00:27:22:e4:fb:d9 -S '' file /etc/ppp/pppoe-server-options 10.0.0.253:10.0.0.163 nodetach noaccomp nobsdcomp nodeflate nopcomp novj novjccomp default-asyncmap

Edited 2013-03-14 11:24:12 by yKpon

Alexey Osipov · 2013-03-15 02:23:14

Лог приведен на момент до "пустил роутер абонента в перезагрузку" или после?

Alexey Osipov · 2013-03-15 02:25:20

в поле IP у меня сейчас 2 адреса, это IP-туннеля и IP-локальный, может stg слышит любой из адресов (в данном случае локальный) и думает всё OK, не?

Такое возможно только в случае, если на каком-то из этих IP ещё запущен inetaccess, который авторизовался совместно с purestg2. Просто наличие "доступного" IP не должно приводить к автоматической авторизации с него.

yKpon · 2013-03-15 05:09:12

лог ДО перезапуска

вечером снова повторилось у нескольких абонентов, ррр интерфейса нет, в stg статус online, в процессах соответствующий pppd есть

Edited 2013-03-15 05:15:27 by yKpon

Alexey Osipov · 2013-03-15 05:30:09

Значит надо искать потерянный интерфейс.

По логу видно, что клиент вполне себе авторизовался и пока жив. Ты лог с grep-ом приводишь. Может быть там в соседних строчках от других частей системы есть какие-то сообщения, которые могут пролить свет на просиходящее?

Тут ещё какой момент есть. Подключение PPP-интефрейса происходит в несколько этапов, среди которых есть auth_up, ip_up, ip_down и link_down. В процессе подключения сначала происходит auth_up (когда пароль пользователя уже проверен, но IP адрес на интерфейс ещё не назначен), потом ip_up (когда на интерфейс назначен IP адрес и он полностью работоспособен). В процесс отключения сначала происходит ip_down (с интерфейса снимается IP адрес, но интерфейс всё ещё существует, PPPoE или PPtP уровень ещё функционирует), а затем происходит link_down (всё, канальный уровень тоже отключен).

Так вот: purestg2 выполняет подключение абонента в stg в момент ip_up, а отключение - в момент link_down, то есть после полного закрытия туннеля. Есть вероятность, что при переподключении пользователя, старый туннель ещё не полностью закрыт (ip_down произошел, поэтому ты не видишь туннель в ifconfig, а link_down ещё не произошел, поэтому старгейзер все ещё считает клиента онлайн), а пользователь открывает новый туннель, который полностью конфигурируется, доходит до ip_up, purestg2 пытается авторизовать пользователя в старгейзере, но тот ещё онлайн (т.к. старый тунель ещё не полностью закрылся), и purestg2 отказывает в подключении.

Попробуй в сложившейся ситуации поискать пропавший интерфейс не командой "ifconfig", а командой "ifconfig -a", она показывает даже несконфигурированные (нерабочие) интерфейсы.

Alexey Osipov · 2013-03-15 05:32:59

Раньше кстати отключение пользователя в стг висело как-раз на ip_down, а не на link_down. Потом я переделал. Не помню, почему. Надо будет поглядеть по git логам.

yKpon · 2013-03-15 06:03:59

перезагрузил промежуточную железку, связь секунд на 10 пропадала, и вот они 2 красавца

skyprox:~# ifconfig -a

интерфейсы не переименованые, а значит они ещё не добрались до ip-up

ppp5      Link encap:Point-to-Point Protocol  
          inet addr:10.0.0.253  P-t-P:10.168.5.5  Mask:255.255.255.255
          POINTOPOINT NOARP MULTICAST  MTU:1492  Metric:1
          RX packets:8 errors:0 dropped:0 overruns:0 frame:0
          TX packets:3 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3 
          RX bytes:309 (309.0   TX bytes:54 (54.0 
 
ppp22     Link encap:Point-to-Point Protocol  
          inet addr:10.0.0.253  P-t-P:10.168.5.4  Mask:255.255.255.255
          POINTOPOINT NOARP MULTICAST  MTU:1492  Metric:1
          RX packets:3 errors:0 dropped:0 overruns:0 frame:0
          TX packets:3 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3 
          RX bytes:54 (54.0   TX bytes:54 (54.0

Edited 2013-03-15 06:04:31 by yKpon

yKpon · 2013-03-15 06:12:24

ещё раз спровоцировал, и получил 3 неопределённых туннеля ppp11, ppp21 и ppp22
вот читый лог, когда появились эти интерфейсы, в логах девайсы не перегружал

Mar 15 10:09:34 skyprox pppd[14325]: LCP terminated by peer (Peer not responding)
Mar 15 10:09:34 skyprox pppd[14325]: purestg2: User semen disconnected.
Mar 15 10:09:34 skyprox pppd[14325]: purestg2: Disconnected from stargazer.
Mar 15 10:09:34 skyprox pppd[14325]: Couldn't get PPP statistics: No such device
Mar 15 10:09:34 skyprox pppd[14325]: Couldn't get PPP statistics: No such device
Mar 15 10:09:34 skyprox pppd[14325]: ioctl (SIOCGIFFLAGS): No such device (line 2353)
Mar 15 10:09:34 skyprox pppd[14325]: ioctl(SIOCSIFADDR): No such device (line 2513)
Mar 15 10:09:35 skyprox pppoe-server[28081]: Session 55 created for client 00:27:22:e2:7c:62 (10.0.0.184) on eth_vlan51 using Service-Name ''
Mar 15 10:09:35 skyprox pppd[28081]: Plugin purestg2.so loaded.
Mar 15 10:09:35 skyprox pppd[28081]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Chap check is allowed.
Mar 15 10:09:35 skyprox pppd[28081]: pppd 2.4.5 started by root, uid 0
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: ifunit set to 21.
Mar 15 10:09:35 skyprox pppd[28081]: Using interface ppp21
Mar 15 10:09:35 skyprox pppd[28081]: Connect: ppp21 <--> /dev/pts/12
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Chap check is allowed.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Chap check is allowed.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: CHAP started.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Got passwd for user semen.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: IP choose started.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Allowed address.
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: Good address.
Mar 15 10:09:35 skyprox pppd[28081]: local  IP address 10.0.0.253
Mar 15 10:09:35 skyprox pppd[28081]: remote IP address 10.168.5.3
Mar 15 10:09:35 skyprox pppd[28081]: purestg2: User semen connected.
Mar 15 10:09:36 skyprox pppd[15769]: LCP terminated by peer (Peer not responding)
Mar 15 10:09:36 skyprox pppd[15769]: purestg2: User himik disconnected.
Mar 15 10:09:36 skyprox pppd[15769]: purestg2: Disconnected from stargazer.
Mar 15 10:09:36 skyprox pppd[15769]: Couldn't get PPP statistics: No such device
Mar 15 10:09:36 skyprox pppd[15769]: Couldn't get PPP statistics: No such device
Mar 15 10:09:36 skyprox pppd[15769]: ioctl (SIOCGIFFLAGS): No such device (line 2353)
Mar 15 10:09:36 skyprox pppd[15769]: ioctl(SIOCSIFADDR): No such device (line 2513)
Mar 15 10:09:37 skyprox pppoe-server[28444]: Session 56 created for client 00:27:22:e4:fb:d9 (10.0.0.185) on eth_vlan51 using Service-Name ''
Mar 15 10:09:37 skyprox pppd[28444]: Plugin purestg2.so loaded.
Mar 15 10:09:37 skyprox pppd[28444]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Chap check is allowed.
Mar 15 10:09:37 skyprox pppd[28444]: pppd 2.4.5 started by root, uid 0
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: ifunit set to 22.
Mar 15 10:09:37 skyprox pppd[28444]: Using interface ppp22
Mar 15 10:09:37 skyprox pppd[28444]: Connect: ppp22 <--> /dev/pts/13
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Chap check is allowed.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Chap check is allowed.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: CHAP started.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Got passwd for user himik.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: IP choose started.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Allowed address.
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: Good address.
Mar 15 10:09:37 skyprox pppd[28444]: local  IP address 10.0.0.253
Mar 15 10:09:37 skyprox pppd[28444]: remote IP address 10.168.5.4
Mar 15 10:09:37 skyprox pppd[28444]: purestg2: User himik connected.
Mar 15 10:09:37 skyprox pppd[14325]: Connection terminated.
Mar 15 10:09:37 skyprox pppd[14325]: Modem hangup
Mar 15 10:09:37 skyprox pppoe[14327]: read (asyncReadFromPPP): Session 53: Input/output error
Mar 15 10:09:37 skyprox pppd[14325]: Exit.
Mar 15 10:09:37 skyprox pppoe-server[1910]: Session 53 closed for client 00:27:22:e2:7c:62 (10.0.0.182) on eth_vlan51
Mar 15 10:09:37 skyprox pppoe-server[1910]: Sent PADT
Mar 15 10:09:38 skyprox pppd[14163]: LCP terminated by peer (Peer not responding)
Mar 15 10:09:38 skyprox pppd[14163]: purestg2: User varej1 disconnected.
Mar 15 10:09:38 skyprox pppd[14163]: purestg2: Disconnected from stargazer.
Mar 15 10:09:38 skyprox pppd[14163]: Couldn't get PPP statistics: No such device
Mar 15 10:09:38 skyprox pppd[14163]: Couldn't get PPP statistics: No such device
Mar 15 10:09:38 skyprox pppd[14163]: ioctl (SIOCGIFFLAGS): No such device (line 2353)
Mar 15 10:09:38 skyprox pppd[14163]: ioctl(SIOCSIFADDR): No such device (line 2513)
Mar 15 10:09:39 skyprox pppd[15769]: Connection terminated.
Mar 15 10:09:39 skyprox pppd[15769]: Modem hangup
Mar 15 10:09:39 skyprox pppoe[15771]: read (asyncReadFromPPP): Session 54: Input/output error
Mar 15 10:09:39 skyprox pppd[15769]: Exit.
Mar 15 10:09:39 skyprox pppoe-server[1910]: Session 54 closed for client 00:27:22:e4:fb:d9 (10.0.0.183) on eth_vlan51
Mar 15 10:09:39 skyprox pppoe-server[1910]: Sent PADT
Mar 15 10:09:39 skyprox pppoe-server[28789]: Session 57 created for client dc:9f:db:0a:ab:b6 (10.0.0.186) on eth_vlan51 using Service-Name ''
Mar 15 10:09:39 skyprox pppd[28789]: Plugin purestg2.so loaded.
Mar 15 10:09:39 skyprox pppd[28789]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Chap check is allowed.
Mar 15 10:09:39 skyprox pppd[28789]: pppd 2.4.5 started by root, uid 0
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: ifunit set to 11.
Mar 15 10:09:39 skyprox pppd[28789]: Using interface ppp11
Mar 15 10:09:39 skyprox pppd[28789]: Connect: ppp11 <--> /dev/pts/7
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Chap check is allowed.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Chap check is allowed.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: CHAP started.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Got passwd for user varej1.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: IP choose started.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Allowed address.
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: Good address.
Mar 15 10:09:39 skyprox pppd[28789]: local  IP address 10.0.0.253
Mar 15 10:09:39 skyprox pppd[28789]: remote IP address 10.168.5.5
Mar 15 10:09:39 skyprox pppd[28789]: purestg2: User varej1 connected.
Mar 15 10:09:41 skyprox pppd[14163]: Connection terminated.
Mar 15 10:09:41 skyprox pppd[14163]: Modem hangup
Mar 15 10:09:41 skyprox pppoe[14165]: read (asyncReadFromPPP): Session 52: Input/output error
Mar 15 10:09:41 skyprox pppd[14163]: Exit.
Mar 15 10:09:41 skyprox pppoe-server[1910]: Session 52 closed for client dc:9f:db:0a:ab:b6 (10.0.0.181) on eth_vlan51
Mar 15 10:09:41 skyprox pppoe-server[1910]: Sent PADT

Edited 2013-03-15 06:18:43 by yKpon

Alexey Osipov · 2013-03-15 15:29:49

В логе, впрочем, тоже все хорошо со стороны purestg2 - все запрошенные подключения обслужены и пользователи подключены. Отлупов из-за повисших туннелей не наблюдается.

Да и сама ситуация, судя по логу, немного отличается от той, что я описал выше: здесь отключение пользователя со стороны purestg2 происходит четко до новой попытки его подключения:

Mar 15 10:09:34 skyprox pppd[14325]: purestg2: User semen disconnected.

Mar 15 10:09:35 skyprox pppd[28081]: purestg2: User semen connected.

yKpon · 2013-03-15 15:53:50

откуда тогда эти непонятные "не RUNNING" интерфейсы? почему интерфейс падает и появляется заново в непонятном состоянии при этом в биллинге он не срывается, вообще не понятно как-то

Edited 2013-03-15 15:54:32 by yKpon

Alexey Osipov · 2013-03-16 17:34:24

откуда тогда эти непонятные "не RUNNING" интерфейсы?

Это те самые недозакрытые интерфейсы, у которых IP уровень уже отключен (поэтому он не RUNNING), а канальный уровень (PPPoE) ещё жив.

Рассмотрим, например, Семёна:

0. pppd решает, что Семён более недоступен ("клиент не отвечает") и начинает процесс закрытия соединения:

Mar 15 10:09:34 skyprox pppd[14325]: LCP terminated by peer (Peer not responding)

1. purestg2 получает сигнал от pppd, что случился auth_down, отключает пользователя semen от старгейзера и сам отключается от старгейзерного сокета:

Mar 15 10:09:34 skyprox pppd[14325]: purestg2: User semen disconnected.

Mar 15 10:09:34 skyprox pppd[14325]: purestg2: Disconnected from stargazer.

2. Семён пытается переподключится, открывая тем самым новую PPPoE сессию:

Mar 15 10:09:35 skyprox pppoe-server[28081]: Session 55 created for client 00:27:22:e2:7c:62 (10.0.0.184) on eth_vlan51 using Service-Name ''

3. pppoe-server стартует новый pppd, который в свою очередь создает новый интерфейс и грузит плагин purestg2:

Mar 15 10:09:35 skyprox pppd[28081]: Plugin purestg2.so loaded.

Mar 15 10:09:35 skyprox pppd[28081]: Stargazer (purestg2 2.4) auth plugin initialized.

4. purestg2, проверив пароль, подключает пользователя semen в старгейзере:

Mar 15 10:09:35 skyprox pppd[28081]: purestg2: User semen connected.

5. старый pppd наконец умирает, забирая за собой и старый интерфейс:

Mar 15 10:09:37 skyprox pppd[14325]: Exit.

6. закрывается предыдущая PPPoE сессия Семёна:

Mar 15 10:09:37 skyprox pppoe-server[1910]: Session 53 closed for client 00:27:22:e2:7c:62 (10.0.0.182) on eth_vlan51

Mar 15 10:09:37 skyprox pppoe-server[1910]: Sent PADT

На шагах 0-1 пользователь semen в старгейзере online.

На шагах 2-3 пользователь semen в старгейзере offline.

На шагах 4-6 пользователь semen в старгейзере снова online.

На шагах 3-5 существует одновременно две PPPoE сессии с Семёном (и, соответственно, два pppd), что и порождает эти "непонятные интерфейсы".

Аналогичный процесс прослеживается и для остальных пользователей, которых видно в логе.

почему интерфейс падает и появляется заново в непонятном состоянии при этом в биллинге он не срывается, вообще не понятно как-то

Интерфейс "падает", потому что происходит разрыв соединения. Но "падает" он не сразу, а поэтапно. В биллинге пользователь отключается ещё до того, как туннель полностью закрыт, поэтому наличие этого недозакрытого интерфейса не препятствует биллингу авторизовать пользователя по новому туннелю.

yKpon · 2013-03-18 10:18:50

ну это же не нормально, не долно быть висяков таких =)
ещё раз спровоцировал, логин пользователя varej1, pppoe концентратор на eth_varej1

Mar 18 14:04:40 skyprox pppoe-server[6054]: Session 25 created for client dc:9f:db:0a:ab:b6 (10.0.0.154) on eth_varej1 using Service-Name ''
Mar 18 14:04:40 skyprox pppd[6054]: Plugin purestg2.so loaded.
Mar 18 14:04:40 skyprox pppd[6054]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Chap check is allowed.
Mar 18 14:04:40 skyprox pppd[6054]: pppd 2.4.5 started by root, uid 0
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: ifunit set to 17.
Mar 18 14:04:40 skyprox pppd[6054]: Using interface ppp17
Mar 18 14:04:40 skyprox pppd[6054]: Connect: ppp17 <--> /dev/pts/0
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Chap check is allowed.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Chap check is allowed.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: CHAP started.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Got passwd for user varej1.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: IP choose started.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Allowed address.
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: Good address.
Mar 18 14:04:40 skyprox pppd[6054]: local  IP address 10.0.0.253
Mar 18 14:04:40 skyprox pppd[6054]: remote IP address 10.168.5.5
Mar 18 14:04:40 skyprox pppd[6054]: purestg2: User varej1 connected.
Mar 18 14:05:56 skyprox pppoe-server[8349]: Session 28 created for client dc:9f:db:0a:ab:b6 (10.0.0.157) on eth_varej1 using Service-Name ''
Mar 18 14:05:56 skyprox pppd[8349]: Plugin purestg2.so loaded.
Mar 18 14:05:56 skyprox pppd[8349]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Chap check is allowed.
Mar 18 14:05:56 skyprox pppd[8349]: pppd 2.4.5 started by root, uid 0
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: ifunit set to 18.
Mar 18 14:05:56 skyprox pppd[8349]: Using interface ppp18
Mar 18 14:05:56 skyprox pppd[8349]: Connect: ppp18 <--> /dev/pts/10
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Chap check is allowed.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Chap check is allowed.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: CHAP started.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Got passwd for user varej1.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: IP choose started.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Allowed address.
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: Good address.
Mar 18 14:05:56 skyprox pppd[8349]: local  IP address 10.0.0.253
Mar 18 14:05:56 skyprox pppd[8349]: remote IP address 10.168.5.5
Mar 18 14:05:56 skyprox pppd[6054]: purestg2: stargazer socket has just been closed. Terminating connection.
Mar 18 14:05:56 skyprox pppd[6054]: Terminating on signal 15
Mar 18 14:05:56 skyprox pppd[6054]: purestg2: Can't disconnect user varej1
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: User varej1 connected.
Mar 18 14:05:56 skyprox pppd[6054]: Couldn't get PPP statistics: No such device
Mar 18 14:05:56 skyprox pppd[6054]: Couldn't get PPP statistics: No such device
Mar 18 14:05:56 skyprox pppd[6054]: ioctl (SIOCGIFFLAGS): No such device (line 2353)
Mar 18 14:05:56 skyprox pppd[6054]: ioctl(SIOCSIFADDR): No such device (line 2513)
Mar 18 14:06:02 skyprox pppd[6054]: Connection terminated.
Mar 18 14:06:02 skyprox pppd[6054]: Modem hangup
Mar 18 14:06:02 skyprox pppoe[6056]: read (asyncReadFromPPP): Session 25: Input/output error
Mar 18 14:06:02 skyprox pppd[6054]: Exit.
Mar 18 14:06:02 skyprox pppoe-server[1910]: Session 25 closed for client dc:9f:db:0a:ab:b6 (10.0.0.154) on eth_varej1
Mar 18 14:06:02 skyprox pppoe-server[1910]: Sent PADT
Mar 18 14:06:26 skyprox pppd[8349]: LCP terminated by peer (User request)
Mar 18 14:06:26 skyprox pppd[8349]: purestg2: User varej1 disconnected.
Mar 18 14:06:26 skyprox pppd[8349]: purestg2: Disconnected from stargazer.
Mar 18 14:06:26 skyprox pppd[8349]: Connect time 0.5 minutes.
Mar 18 14:06:26 skyprox pppd[8349]: Sent 0 bytes, received 0 bytes.
Mar 18 14:06:29 skyprox pppd[8349]: Connection terminated.
Mar 18 14:06:29 skyprox pppd[8349]: Modem hangup
Mar 18 14:06:29 skyprox pppoe[8351]: read (asyncReadFromPPP): Session 28: Input/output error
Mar 18 14:06:29 skyprox pppd[8349]: Exit.
Mar 18 14:06:29 skyprox pppoe-server[1910]: Session 28 closed for client dc:9f:db:0a:ab:b6 (10.0.0.157) on eth_varej1
Mar 18 14:06:29 skyprox pppoe-server[1910]: Sent PADT
Mar 18 14:07:11 skyprox pppoe-server[11212]: Session 27 created for client dc:9f:db:0a:ab:b6 (10.0.0.156) on eth_varej1 using Service-Name ''
Mar 18 14:07:11 skyprox pppd[11212]: Plugin purestg2.so loaded.
Mar 18 14:07:11 skyprox pppd[11212]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Chap check is allowed.
Mar 18 14:07:11 skyprox pppd[11212]: pppd 2.4.5 started by root, uid 0
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: ifunit set to 17.
Mar 18 14:07:11 skyprox pppd[11212]: Using interface ppp17
Mar 18 14:07:11 skyprox pppd[11212]: Connect: ppp17 <--> /dev/pts/0
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Chap check is allowed.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Chap check is allowed.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: CHAP started.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Got passwd for user varej1.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: IP choose started.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Allowed address.
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: Good address.
Mar 18 14:07:11 skyprox pppd[11212]: local  IP address 10.0.0.253
Mar 18 14:07:11 skyprox pppd[11212]: remote IP address 10.168.5.5
Mar 18 14:07:11 skyprox pppd[11212]: purestg2: User varej1 connected.

по шагам:
Mon Mar 18 14:04:40 MSK 2013 - перезагрузка роутера и юзер успешно логинится
Mon Mar 18 14:05:56 MSK 2013 - перегружаю один маршрутизатор на пути к нему что вызывает "глюк"
Mon Mar 18 14:07:11 MSK 2013 - снова перегружаю роутер, после чего он успешно соединяется

после "провала" связи мы видим он пытается подключиться, но не может отключить предыдущую авторизацю в STG
Mar 18 14:05:56 skyprox pppd[6054]: purestg2: Can't disconnect user varej1

ещё разок

Mar 18 14:43:43 skyprox pppoe-server[7224]: Session 29 created for client dc:9f:db:0a:ab:b6 (10.0.0.158) on eth_varej1 using Service-Name ''
Mar 18 14:43:43 skyprox pppd[7224]: Plugin purestg2.so loaded.
Mar 18 14:43:43 skyprox pppd[7224]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Chap check is allowed.
Mar 18 14:43:43 skyprox pppd[7224]: pppd 2.4.5 started by root, uid 0
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: ifunit set to 6.
Mar 18 14:43:43 skyprox pppd[7224]: Using interface ppp6
Mar 18 14:43:43 skyprox pppd[7224]: Connect: ppp6 <--> /dev/pts/0
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Chap check is allowed.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Chap check is allowed.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: CHAP started.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Got passwd for user varej1.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: IP choose started.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Allowed address.
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: Good address.
Mar 18 14:43:43 skyprox pppd[7224]: local  IP address 10.0.0.253
Mar 18 14:43:43 skyprox pppd[7224]: remote IP address 10.168.5.5
Mar 18 14:43:43 skyprox pppd[7224]: purestg2: User varej1 connected.
Mar 18 14:45:39 skyprox pppoe-server[10489]: Session 30 created for client dc:9f:db:0a:ab:b6 (10.0.0.159) on eth_varej1 using Service-Name ''
Mar 18 14:45:39 skyprox pppd[10489]: Plugin purestg2.so loaded.
Mar 18 14:45:39 skyprox pppd[10489]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:45:39 skyprox pppd[10489]: purestg2: Chap check is allowed.
Mar 18 14:45:39 skyprox pppd[10489]: pppd 2.4.5 started by root, uid 0
Mar 18 14:45:39 skyprox pppd[10489]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:45:39 skyprox pppd[10489]: purestg2: ifunit set to 17.
Mar 18 14:45:39 skyprox pppd[10489]: Using interface ppp17
Mar 18 14:45:39 skyprox pppd[10489]: Connect: ppp17 <--> /dev/pts/12
Mar 18 14:45:40 skyprox pppd[10489]: purestg2: Chap check is allowed.
Mar 18 14:45:40 skyprox pppd[10489]: purestg2: Chap check is allowed.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: CHAP started.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: Got passwd for user varej1.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: IP choose started.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: Allowed address.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: Good address.
Mar 18 14:45:42 skyprox pppd[10489]: local  IP address 10.0.0.253
Mar 18 14:45:42 skyprox pppd[10489]: remote IP address 10.168.5.5
Mar 18 14:45:42 skyprox pppd[7224]: purestg2: stargazer socket has just been closed. Terminating connection.
Mar 18 14:45:42 skyprox pppd[10489]: purestg2: User varej1 connected.
Mar 18 14:45:42 skyprox pppd[7224]: Terminating on signal 15
Mar 18 14:45:42 skyprox pppd[7224]: purestg2: Can't disconnect user varej1
Mar 18 14:45:42 skyprox pppd[7224]: Couldn't get PPP statistics: No such device
Mar 18 14:45:42 skyprox pppd[7224]: Couldn't get PPP statistics: No such device
Mar 18 14:45:42 skyprox pppd[7224]: ioctl (SIOCGIFFLAGS): No such device (line 2353)
Mar 18 14:45:42 skyprox pppd[7224]: ioctl(SIOCSIFADDR): No such device (line 2513)
Mar 18 14:45:43 skyprox pppd[7224]: purestg2: No ping from stargazer, exiting.
Mar 18 14:45:43 skyprox pppd[7224]: Terminating on signal 15
Mar 18 14:45:48 skyprox pppd[7224]: Connection terminated.
Mar 18 14:45:48 skyprox pppd[7224]: Modem hangup
Mar 18 14:45:48 skyprox pppoe[7226]: read (asyncReadFromPPP): Session 29: Input/output error
Mar 18 14:45:48 skyprox pppd[7224]: Exit.
Mar 18 14:45:48 skyprox pppoe-server[1910]: Session 29 closed for client dc:9f:db:0a:ab:b6 (10.0.0.158) on eth_varej1
Mar 18 14:45:48 skyprox pppoe-server[1910]: Sent PADT
Mar 18 14:47:29 skyprox pppd[10489]: LCP terminated by peer (User request)
Mar 18 14:47:29 skyprox pppd[10489]: purestg2: User varej1 disconnected.
Mar 18 14:47:29 skyprox pppd[10489]: purestg2: Disconnected from stargazer.
Mar 18 14:47:29 skyprox pppd[10489]: Connect time 1.8 minutes.
Mar 18 14:47:29 skyprox pppd[10489]: Sent 0 bytes, received 0 bytes.
Mar 18 14:47:32 skyprox pppd[10489]: Connection terminated.
Mar 18 14:47:32 skyprox pppd[10489]: Modem hangup
Mar 18 14:47:32 skyprox pppoe[10491]: read (asyncReadFromPPP): Session 30: Input/output error
Mar 18 14:47:32 skyprox pppd[10489]: Exit.
Mar 18 14:47:32 skyprox pppoe-server[1910]: Session 30 closed for client dc:9f:db:0a:ab:b6 (10.0.0.159) on eth_varej1
Mar 18 14:47:32 skyprox pppoe-server[1910]: Sent PADT
Mar 18 14:48:12 skyprox pppoe-server[15528]: Session 26 created for client dc:9f:db:0a:ab:b6 (10.0.0.155) on eth_varej1 using Service-Name ''
Mar 18 14:48:12 skyprox pppd[15528]: Plugin purestg2.so loaded.
Mar 18 14:48:12 skyprox pppd[15528]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: Chap check is allowed.
Mar 18 14:48:12 skyprox pppd[15528]: pppd 2.4.5 started by root, uid 0
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: ifunit set to 6.
Mar 18 14:48:12 skyprox pppd[15528]: Using interface ppp6
Mar 18 14:48:12 skyprox pppd[15528]: Connect: ppp6 <--> /dev/pts/0
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: Chap check is allowed.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: Chap check is allowed.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: CHAP started.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: Got passwd for user varej1.
Mar 18 14:48:12 skyprox pppd[15528]: purestg2: IP choose started.
Mar 18 14:48:13 skyprox pppd[15528]: purestg2: Allowed address.
Mar 18 14:48:13 skyprox pppd[15528]: purestg2: Good address.
Mar 18 14:48:13 skyprox pppd[15528]: local  IP address 10.0.0.253
Mar 18 14:48:13 skyprox pppd[15528]: remote IP address 10.168.5.5
Mar 18 14:48:13 skyprox pppd[15528]: purestg2: User varej1 connected.

Mon Mar 18 14:43:43 MSK 2013 - рестарт роутера и успешное подклюдчение
Mon Mar 18 14:45:42 MSK 2013 - провоцируем завис
Mon Mar 18 14:48:13 MSK 2013 - ещё раз перезагруз роутера и успешное переподключение

постоянно дёргать вручную это же не выход из положения правильно

Edited 2013-03-18 10:55:45 by yKpon

Alexey Osipov · 2013-03-19 05:13:23

Воооот. Вот это уже интереснее.

Хотелось бы ещё увидеть лог старгейзера в момент:

Mar 18 14:05:56 skyprox pppd[8349]: local IP address 10.0.0.253
Mar 18 14:05:56 skyprox pppd[8349]: remote IP address 10.168.5.5
Mar 18 14:05:56 skyprox pppd[6054]: purestg2: stargazer socket has just been closed. Terminating connection.
Mar 18 14:05:56 skyprox pppd[6054]: Terminating on signal 15
Mar 18 14:05:56 skyprox pppd[6054]: purestg2: Can't disconnect user varej1
Mar 18 14:05:56 skyprox pppd[8349]: purestg2: User varej1 connected.

Пока похоже на то, что в конфиге purestg2 включена опция kickprevious. Когда новый pppd[8349] пытаеся в стг подключить пользователя с новой сессии, purestg2 со стороны старгейзера сначала разрывает соединение со старым pppd[6054]:

Mar 18 14:05:56 skyprox pppd[6054]: purestg2: stargazer socket has just been closed. Terminating connection.

а потом авторизовывает пользователя с нового pppd:

Mar 18 14:05:56 skyprox pppd[8349]: purestg2: User varej1 connected.

Старый pppd[6054], увидев, что соединение со старгейзером закрылось, начинает медленно умирать (штатным образом):

Mar 18 14:05:56 skyprox pppd[6054]: Terminating on signal 15

По пути, он пытается снять авторизацию со старого пользователя в старгейзере, но не может этого сделать:

Mar 18 14:05:56 skyprox pppd[6054]: purestg2: Can't disconnect user varej1

Но это и логично, ведь соединение со старгейзером было закрыто самим старгейзером. А перед закрытием соеднения старгейзер сам снял авторизацию со старого пользователя.

Через 6 секунд закрывается и старая PPPoE сессия:

Mar 18 14:06:02 skyprox pppd[6054]: Exit.
Mar 18 14:06:02 skyprox pppoe-server[1910]: Session 25 closed for client dc:9f:db:0a:ab:b6 (10.0.0.154) on eth_varej1
Mar 18 14:06:02 skyprox pppoe-server[1910]: Sent PADT

А вот дальше (через 20 секунд) происходит интересное - новый pppd[8349] получает сигнал на завершение соединения. Но получает он его не от purestg2, а от пользователя(!):

Mar 18 14:06:26 skyprox pppd[8349]: LCP terminated by peer (User request)

Дальше всё происходит штатно, purestg2 видит, что новое соединение закрывается и отключает пользователя в старгейзере:

Mar 18 14:06:26 skyprox pppd[8349]: purestg2: User varej1 disconnected.
Mar 18 14:06:26 skyprox pppd[8349]: purestg2: Disconnected from stargazer.

Ну и в конце концов новый pppd умирает и новая PPPoE сессия тоже закрывается:

Mar 18 14:06:29 skyprox pppd[8349]: Exit.
Mar 18 14:06:29 skyprox pppoe-server[1910]: Session 28 closed for client dc:9f:db:0a:ab:b6 (10.0.0.157) on eth_varej1
Mar 18 14:06:29 skyprox pppoe-server[1910]: Sent PADT

Внимание вопрос: почему пользователь (роутер или кто у тебя там на том конце?) просит разорвать соединение?

Alexey Osipov · 2013-03-19 05:27:52

У меня есть одно предоположение:

Получается так, что клиенту приходится в определнный интервал времени держать одновременно два PPPoE подключения к твоему серверу (когда он уже начал новую сессию, а старая ещё не закрылась окончательно). Потом, когда старая сессия закрывается, сервер шлет клиенту пакет PADT (видно в логах), этот пакет означает буквально "завершить сессию". Возможно, клиент при этом считает, что этот пакет относится к новой сессии, а не к старой. И, отреагировав на пакет, закрывает новую сессию.

yKpon · 2013-03-19 05:50:52

да, опция kickprevious включена, отключить?

вот что в логах STG в это время

2013-03-18 14:05:55 -- purestg2: Accepted new client connection (socket=28)
2013-03-18 14:05:55 -- purestg2: Terminating previous session (oldsocket=27) for user "varej1"
2013-03-18 14:05:55 -- purestg2: User varej1 (socket=28) is connected.

Edited 2013-03-19 05:51:17 by yKpon

yKpon · 2013-03-19 06:54:49

отключил kickprevious

провоцируем и получаем

skyprox:/# ifconfig -a ppp17

ppp17 Link encap:Point-to-Point Protocol

inet addr:10.0.0.253 P-t-P:10.168.5.5 Mask:255.255.255.255

POINTOPOINT NOARP MULTICAST MTU:1492 Metric:1

RX packets:3 errors:0 dropped:0 overruns:0 frame:0

TX packets:3 errors:0 dropped:0 overruns:0 carrier:0

collisions:0 txqueuelen:3

RX bytes:54 (54.0

TX bytes:54 (54.0

syslog

Mar 19 10:42:53 skyprox pppoe-server[22075]: Session 61 created for client dc:9f:db:0a:ab:b6 (10.0.0.190) on eth_varej1 using Service-Name ''

Mar 19 10:42:53 skyprox pppd[22075]: Plugin purestg2.so loaded.

Mar 19 10:42:53 skyprox pppd[22075]: Stargazer (purestg2 2.4) auth plugin initialized.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Chap check is allowed.

Mar 19 10:42:53 skyprox pppd[22075]: pppd 2.4.5 started by root, uid 0

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Connected to stargazer via /var/run/purestg2.sock.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: ifunit set to 15.

Mar 19 10:42:53 skyprox pppd[22075]: Using interface ppp15

Mar 19 10:42:53 skyprox pppd[22075]: Connect: ppp15 <--> /dev/pts/10

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Chap check is allowed.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: CHAP started.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Got passwd for user varej1.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: IP choose started.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Allowed address.

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: Good address.

Mar 19 10:42:53 skyprox pppd[22075]: local IP address 10.0.0.253

Mar 19 10:42:53 skyprox pppd[22075]: remote IP address 10.168.5.5

Mar 19 10:42:53 skyprox pppd[22075]: purestg2: User varej1 connected.

Mar 19 10:43:56 skyprox pppd[22075]: LCP terminated by peer (Peer not responding)

Mar 19 10:43:56 skyprox pppd[22075]: purestg2: User varej1 disconnected.

Mar 19 10:43:56 skyprox pppd[22075]: purestg2: Disconnected from stargazer.

Mar 19 10:43:56 skyprox pppd[22075]: Couldn't get PPP statistics: No such device

Mar 19 10:43:56 skyprox pppd[22075]: ioctl (SIOCGIFFLAGS): No such device (line 2353)

Mar 19 10:43:56 skyprox pppd[22075]: ioctl(SIOCSIFADDR): No such device (line 2513)

Mar 19 10:43:57 skyprox pppoe-server[23710]: Session 64 created for client dc:9f:db:0a:ab:b6 (10.0.0.193) on eth_varej1 using Service-Name ''

Mar 19 10:43:57 skyprox pppd[23710]: Plugin purestg2.so loaded.

Mar 19 10:43:57 skyprox pppd[23710]: Stargazer (purestg2 2.4) auth plugin initialized.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Chap check is allowed.

Mar 19 10:43:57 skyprox pppd[23710]: pppd 2.4.5 started by root, uid 0

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Connected to stargazer via /var/run/purestg2.sock.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: ifunit set to 17.

Mar 19 10:43:57 skyprox pppd[23710]: Using interface ppp17

Mar 19 10:43:57 skyprox pppd[23710]: Connect: ppp17 <--> /dev/pts/11

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Chap check is allowed.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: CHAP started.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Got passwd for user varej1.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: IP choose started.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Allowed address.

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: Good address.

Mar 19 10:43:57 skyprox pppd[23710]: local IP address 10.0.0.253

Mar 19 10:43:57 skyprox pppd[23710]: remote IP address 10.168.5.5

Mar 19 10:43:57 skyprox pppd[23710]: purestg2: User varej1 connected.

Mar 19 10:43:59 skyprox pppd[22075]: Connection terminated.

Mar 19 10:43:59 skyprox pppd[22075]: Modem hangup

Mar 19 10:43:59 skyprox pppoe[22077]: read (asyncReadFromPPP): Session 61: Input/output error

Mar 19 10:43:59 skyprox pppd[22075]: Exit.

Mar 19 10:43:59 skyprox pppoe-server[1910]: Session 61 closed for client dc:9f:db:0a:ab:b6 (10.0.0.190) on eth_varej1

Mar 19 10:43:59 skyprox pppoe-server[1910]: Sent PADT

stargazer.log

2013-03-19 10:42:53 -- purestg2: Accepted new client connection (socket=24)

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=5, login=

2013-03-19 10:42:53 -- purestg2: reply: type=5, login=, result=1

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=7, login=varej1

2013-03-19 10:42:53 -- purestg2: Got ipparam: ""

2013-03-19 10:42:53 -- purestg2: reply: type=7, login=varej1, result=1

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=3, login=varej1

2013-03-19 10:42:53 -- purestg2: reply: type=3, login=varej1, result=1

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=4, login=varej1

2013-03-19 10:42:53 -- purestg2: reply: type=4, login=varej1, result=1

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=4, login=varej1

2013-03-19 10:42:53 -- purestg2: reply: type=4, login=varej1, result=1

2013-03-19 10:42:53 -- purestg2: request(socket=24): type=1, login=varej1

2013-03-19 10:42:53 -- purestg2: Watchdog timer for user "varej1" submitted on 1363675433

2013-03-19 10:42:53 -- purestg2: User varej1 (socket=24) is connected.

2013-03-19 10:42:53 -- purestg2: reply: type=1, login=varej1, result=1

2013-03-19 10:43:02 -- purestg2: request(socket=20): type=6, login=lerm1

2013-03-19 10:43:02 -- purestg2: PING from user lerm1 (socket=20)

2013-03-19 10:43:02 -- purestg2: Watchdog timer for user "lerm1" submitted on 1363675442

2013-03-19 10:43:02 -- purestg2: reply: type=6, login=lerm1, result=1

2013-03-19 10:43:02 -- purestg2: request(socket=21): type=6, login=jn

2013-03-19 10:43:02 -- purestg2: PING from user jn (socket=21)

2013-03-19 10:43:02 -- purestg2: Watchdog timer for user "jn" submitted on 1363675442

2013-03-19 10:43:02 -- purestg2: reply: type=6, login=jn, result=1

2013-03-19 10:43:02 -- purestg2: request(socket=22): type=6, login=marina

2013-03-19 10:43:02 -- purestg2: PING from user marina (socket=22)

2013-03-19 10:43:02 -- purestg2: Watchdog timer for user "marina" submitted on 1363675442

2013-03-19 10:43:02 -- purestg2: reply: type=6, login=marina, result=1

2013-03-19 10:43:02 -- purestg2: request(socket=23): type=6, login=test

2013-03-19 10:43:02 -- purestg2: PING from user test (socket=23)

2013-03-19 10:43:02 -- purestg2: Watchdog timer for user "test" submitted on 1363675443

2013-03-19 10:43:02 -- purestg2: reply: type=6, login=test, result=1

2013-03-19 10:43:17 -- purestg2: request(socket=25): type=6, login=qwest

2013-03-19 10:43:17 -- purestg2: PING from user qwest (socket=25)

2013-03-19 10:43:17 -- purestg2: Watchdog timer for user "qwest" submitted on 1363675457

2013-03-19 10:43:17 -- purestg2: reply: type=6, login=qwest, result=1

2013-03-19 10:43:25 -- purestg2: request(socket=14): type=6, login=tun

2013-03-19 10:43:25 -- purestg2: PING from user tun (socket=14)

2013-03-19 10:43:25 -- purestg2: Watchdog timer for user "tun" submitted on 1363675466

2013-03-19 10:43:25 -- purestg2: reply: type=6, login=tun, result=1

2013-03-19 10:43:26 -- purestg2: request(socket=19): type=6, login=guryan

2013-03-19 10:43:26 -- purestg2: PING from user guryan (socket=19)

2013-03-19 10:43:26 -- purestg2: Watchdog timer for user "guryan" submitted on 1363675467

2013-03-19 10:43:26 -- purestg2: reply: type=6, login=guryan, result=1

2013-03-19 10:43:29 -- purestg2: request(socket=16): type=6, login=mok

2013-03-19 10:43:29 -- purestg2: PING from user mok (socket=16)

2013-03-19 10:43:29 -- purestg2: Watchdog timer for user "mok" submitted on 1363675470

2013-03-19 10:43:29 -- purestg2: reply: type=6, login=mok, result=1

2013-03-19 10:43:30 -- purestg2: request(socket=15): type=6, login=master

2013-03-19 10:43:30 -- purestg2: PING from user master (socket=15)

2013-03-19 10:43:30 -- purestg2: Watchdog timer for user "master" submitted on 1363675470

2013-03-19 10:43:30 -- purestg2: reply: type=6, login=master, result=1

2013-03-19 10:43:33 -- purestg2: request(socket=17): type=6, login=medik

2013-03-19 10:43:33 -- purestg2: PING from user medik (socket=17)

2013-03-19 10:43:33 -- purestg2: Watchdog timer for user "medik" submitted on 1363675473

2013-03-19 10:43:33 -- purestg2: reply: type=6, login=medik, result=1

2013-03-19 10:43:45 -- purestg2: request(socket=18): type=6, login=a07

2013-03-19 10:43:45 -- purestg2: PING from user a07 (socket=18)

2013-03-19 10:43:45 -- purestg2: Watchdog timer for user "a07" submitted on 1363675485

2013-03-19 10:43:45 -- purestg2: reply: type=6, login=a07, result=1

2013-03-19 10:43:53 -- purestg2: request(socket=24): type=6, login=varej1

2013-03-19 10:43:53 -- purestg2: PING from user varej1 (socket=24)

2013-03-19 10:43:53 -- purestg2: Watchdog timer for user "varej1" submitted on 1363675493

2013-03-19 10:43:53 -- purestg2: reply: type=6, login=varej1, result=1

2013-03-19 10:43:56 -- purestg2: request(socket=24): type=2, login=varej1

2013-03-19 10:43:56 -- purestg2: User varej1 (socket=24) is disconnected.

2013-03-19 10:43:56 -- purestg2: reply: type=2, login=varej1, result=1

2013-03-19 10:43:57 -- purestg2: Accepted new client connection (socket=26)

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=5, login=

2013-03-19 10:43:57 -- purestg2: reply: type=5, login=, result=1

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=7, login=varej1

2013-03-19 10:43:57 -- purestg2: Got ipparam: ""

2013-03-19 10:43:57 -- purestg2: reply: type=7, login=varej1, result=1

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=3, login=varej1

2013-03-19 10:43:57 -- purestg2: reply: type=3, login=varej1, result=1

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=4, login=varej1

2013-03-19 10:43:57 -- purestg2: reply: type=4, login=varej1, result=1

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=4, login=varej1

2013-03-19 10:43:57 -- purestg2: reply: type=4, login=varej1, result=1

2013-03-19 10:43:57 -- purestg2: request(socket=26): type=1, login=varej1

2013-03-19 10:43:57 -- purestg2: Watchdog timer for user "varej1" submitted on 1363675497

2013-03-19 10:43:57 -- purestg2: User varej1 (socket=26) is connected.

2013-03-19 10:43:57 -- purestg2: reply: type=1, login=varej1, result=1

Edited 2013-03-19 06:56:29 by yKpon

Alexey Osipov · 2013-03-19 15:59:15

Кусочек лога старгейзера, который я просил выше, подтверждает сказанное выше.

В последних логах проблема, которую я отметил выше жирным шрифтом, не видна: тут все вообще хорошо.

Давай вернемся к началу: в чем конкретно проблема?

yKpon · 2013-03-19 16:32:32

так проблема в том что если секунд на 10-15 пропадает связь на пути к клиенту получается вот такой не определённый интерфейс и интернет не работает, помогает только перезагрузка роутера, это ведь не совсем гуманное решение, должно переподключаться само =)

нормальный интерфейс для varej1 должен быть таким

skyprox:/# ifconfig vpn_varej1
vpn_varej1 Link encap:Point-to-Point Protocol
          inet addr:10.0.0.253  P-t-P:10.168.5.5  Mask:255.255.255.255
          UP POINTOPOINT RUNNING NOARP MULTICAST  MTU:1492  Metric:1
          RX packets:5 errors:0 dropped:0 overruns:0 frame:0
          TX packets:3 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3
          RX bytes:134 (134.0   TX bytes:54 (54.0

Edited 2013-03-19 16:33:40 by yKpon

Alexey Osipov · 2013-03-20 00:39:54

так проблема в том что если секунд на 10-15 пропадает связь на пути к клиенту получается вот такой не определённый интерфейс и интернет не работает, помогает только перезагрузка роутера, это ведь не совсем гуманное решение, должно переподключаться само =)

Так судя по логам, оно и переподключается. И даже IP выдает. Со стороны purestg2 проблемы не вижу.

Пока единственная проблема, замеченная в логах, - это то, что сам роутер просит разорвать вновь установленное соединение (Connection reset by peer (User request)). Почему он это делает - вопрос. В последних логах с выключенной kickprevious эта строчка для pppd[23710] есть?

Давай ещё покопаем с другой стороны: ты говорил, что у тебя там в ip-up какая-то черная магия с переименованием интерфейсов происходит? Можно взглянуть на содержимое скриптов?

yKpon · 2013-03-20 05:33:22

не пореподключается оно само, это я вручную дёргаю роутер, если этого не сделать неопределённый туннель так и будет висеть, сейчас ещё раз сделал - результат ppp12 не "RUNNING", попыток переподключений НЕТ! STG и purestg2 думает что всё Ok =)

настораживает в логах, что сначала пускает авторизацию, а потом отваливается предыдущий туннель, не в этом ли грабли?

Mar 20 09:25:13 skyprox pppd[5060]: Plugin purestg2.so loaded.
Mar 20 09:25:13 skyprox pppd[5060]: Stargazer (purestg2 2.4) auth plugin initialized.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Chap check is allowed.
Mar 20 09:25:13 skyprox pppd[5060]: pppd 2.4.5 started by root, uid 0
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Connected to stargazer via /var/run/purestg2.sock.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: ifunit set to 12.
Mar 20 09:25:13 skyprox pppd[5060]: Using interface ppp12
Mar 20 09:25:13 skyprox pppd[5060]: Connect: ppp12 <--> /dev/pts/9
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Chap check is allowed.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Chap check is allowed.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: CHAP started.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Got passwd for user varej1.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: IP choose started.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Allowed address.
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: Good address.
Mar 20 09:25:13 skyprox pppd[5060]: local  IP address 10.0.0.253
Mar 20 09:25:13 skyprox pppd[5060]: remote IP address 10.168.5.5
Mar 20 09:25:13 skyprox pppd[5060]: purestg2: User varej1 connected.
Mar 20 09:25:15 skyprox pppd[18271]: Connection terminated.
Mar 20 09:25:15 skyprox pppd[18271]: Modem hangup
Mar 20 09:25:15 skyprox pppoe[18273]: read (asyncReadFromPPP): Session 2: Input/output error
Mar 20 09:25:15 skyprox pppd[18271]: Exit.
Mar 20 09:25:15 skyprox pppoe-server[1910]: Session 2 closed for client dc:9f:db:0a:ab:b6 (10.0.0.131) on eth_varej1
Mar 20 09:25:15 skyprox pppoe-server[1910]: Sent PADT

pid 18271 это и есть предыдущая авторизация

в ip-up у меня вот так

IP=$5
LOGIN=`/usr/bin/mysql -sN -h$DBHOST -u$DBUSER -p$ROOTDBPASS $DBNAME -e "SELECT login FROM users WHERE IP like '$IP,%' OR IP like '$IP'"`
/sbin/ifconfig $1 down
/bin/ip link set $1 name vpn_$LOGIN
/sbin/ifconfig vpn_$LOGIN up

Alexey Osipov · 2013-03-21 02:33:35

Ну и вот. Всё дело в ip-up.

Гляди что происходит:

1. Первое подключение происходит штатно и переименовывается в vpn_varej1.

2. Потом начинается второе подключение, создается новый ppp-интерфейс.

3. Вызывается ip-up для нового интерфейса, который делает ему ifconfig down, новый интерфейс становится не RUNNING.

4(!). ip-up пытается переименовать новый интерфейс в vpn_varej1, но не может этого сделать, т.к. старый интерфейс с таким именем всё ещё существует.

5. Соответственно ifconfig vpn_$LOGIN up ни к чему не приводит, т.к. это имя относится к старому интерфейсу.

6. А новый интерфейс так и остается в состоянии не RUNNING. Думаю, можно его включить банальным ifconfig pppX up.

настораживает в логах, что сначала пускает авторизацию, а потом отваливается предыдущий туннель, не в этом ли грабли?

Грабли в том, что имеющийся ip-up некорректно работает в такой ситуации. Причем, он будет точно так же некорректно работать и без purestg2.

Я в принципе думал, что в подобных случаях могут возникать проблемы - у меня даже TODO в коде написан на этот счет - дожидаться при активной kickprevious завершения работы старого pppd. Хотя в данном случае даже это бы не помогло.

Но у меня, поскольку я не использую переименование интерфейсов и уж тем более не делаю им down, все работает хорошо.

У меня есть идея, как это проблему можно решить со стороны purestg2, но она пока окончательно не оформилась.

Edited 2013-03-21 02:39:56 by Alexey Osipov

yKpon · 2013-03-21 06:59:10

Алексей, всё получилось

только таймаут мне кажется больше одной минуты хотя выставлено 60 сек

       /sbin/ifconfig $1 down
        /bin/ip link set $1 name vpn_$LOGIN
        if [ $? -ne 0 ]; then
            /sbin/ifconfig vpn_$LOGIN 0.0.0.0 down
            /bin/ip link set vpn_$LOGIN name oldvpn_$LOGIN
            /bin/ip link set $1 name vpn_$LOGIN
        fi
        /sbin/ifconfig vpn_$LOGIN up

Edited 2013-03-21 07:15:08 by yKpon

Alexey Osipov · 2013-03-21 13:35:40

Алексей, всё получилось

Это радует.

только таймаут мне кажется больше одной минуты хотя выставлено 60 сек

Тот таймаут, который в настройках purestg2 - это таймаут на случай, если вдруг по какой-то причине пропадет связь между pppd и старгейзером. И он не имеет ничего общего с тем таймаутом, который использует pppd для обнаружения "живучести" канала. Погляди man pppd, там вроде были какие-то настройки нужных тебе таймаутов.

yKpon · 2013-03-21 14:13:24

а если включить kickprevious, то вообще никаких таймаутов не будет ведь, правильно?

Alexey Osipov · 2013-03-21 16:17:30

а если включить kickprevious, то вообще никаких таймаутов не будет ведь, правильно?

По идее - да.

Sign In

purestg2

Recommended Posts

yKpon 8

Link to post

Share on other sites

Top Posters In This Topic

Popular Days

Top Posters In This Topic

Popular Days

Popular Posts

Alexey Osipov 38

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites

Alexey Osipov 38

Link to post

Share on other sites

yKpon 8

Link to post

Share on other sites