Wi-CAT LLC

Wireless Comprehensive Advanced Technology. Build your network now.

Wi-CAT LLC
Навигация Форума
Вы должны войти, чтобы создавать сообщения и темы.

(решено) PPPoE не подключается, если отсутствует связь по WAN час и более

Доброго дня!

Устройство FiberTool FT-AIR-DUO-F
Версия ПО 3.5.1.RU.25062021
Логи и конфиг приложены к посту

Суть проблемы: На роутере настроен WAN в виде PPPoE соединения (VPN в терминологии веб-интерфейса), по которому идет выход в интернет.
Делаем разрыв связи с PPPoE сервером, не обрывая физический ethernet линк на порту WAN, т.е. связность ломается где-то посередине на промежуточном узле. Через 10+ минут простоя роутер не поднимает PPPoE подключение заново и не пытается это сделать, даже если сделать PPPoE сервер доступным. При этом в веб-интерфейсе роутера PPPoE подключение отображается как online. Если в разделе VPN Setup нажать 'Apply and connect', роутер поднимает PPPoE соединение заново. Перезагрузка по питанию или через веб-интерфейс также помогает.

Замечено, что на прошивке, с которой поставляется роутер - 2.9.11.RU.17102020, проблема не проявляется. Ну или проявляется при много большем простое с отсутствии связи, десятки часов или несколько дней.

Также проблема возникает на других роутерах с вашим ПО, FT-AIR-ONE-F и FT-AIR-ONE-G. Если необходимо, могу собрать логи и конфиги на каждую модель.

PPPOE при такой схеме определяет что сессия сдохла исключительно по ответам на LCP echo. Судя по логу число попыток LCP-Echo за время проподания связности не выбрано и интерфейс считается поднятым.

Механика LCP на этот счёт менялась, правда очень давно (вместе с апстримом), так же менялись предустановки настроек LCP-Echo

Включить debug в ppp, попробовать отключить lcp adaptive и поиграться с параметрами LCP. По результатам сообщить.

Сейчас устройство опустит линк и будет пытаться перезванивать если 10 попыток дождаться на LCP-ECHO запрос с интервалом в 15с провалились при этом через PPP интерфейс не прошло ни одного пакета.

Попробую на коленке эмулировать ситуацию, но она покрыта автотестами на самом деле.

Если ничего не выйдет напихаю дебага и попробуем отловить на вашей стороне.

В 3.5.4 чутка переделал логику lcp adaptive в случае если хоть один echo запрос провалился. Так же чутка расширил логирование. Будет доступна в течении дня.

Т.е. описанное выше лучше сразу проделать на ней. На коленке при попытке повторить кейз с 10 минутами всё отрабатывает на раз и без правок.

Видимо есть ещё какой-то триггер для проявления проблемы у вас. Надо разбираться если всё вышеописанное не поможет.

Делаем разрыв связи с PPPoE сервером, не обрывая физический ethernet линк на порту WAN, т.е. связность ломается где-то посередине на промежуточном узле. Через 10+ минут простоя роутер не поднимает PPPoE подключение заново и не пытается это сделать, даже если сделать PPPoE сервер доступным. При этом в веб-интерфейсе роутера PPPoE подключение отображается как online. Если в разделе VPN Setup нажать 'Apply and connect', роутер поднимает PPPoE соединение заново. Перезагрузка по питанию или через веб-интерфейс также помогает.

В общем попытался эмулировать по схеме выше. Проблемы не вижу. См лог.

Jul  9 07:53:33 pppd[5507]: No response to 10 echo-requests
Jul  9 07:53:33 pppd[5507]: Serial link appears to be disconnected.
Jul  9 07:53:33 pppd[5507]: Connect time 3.8 minutes.
Jul  9 07:53:33 pppd[5507]: Sent 1753 bytes, received 1153 bytes.
Jul  9 07:53:33 pppd:down-ppp0: Disable forwarding for ppp0 interface
Jul  9 07:53:33 pppd:down-ppp0: Restore netfilter rules from pppd
Jul  9 07:53:33 pppd:down-ppp0: Flush route and conntrack cache dev ppp0 172.16.200.2
Jul  9 07:53:33 pppd:down-ppp0: Restart need service and rebuild shaper and iptables rules
Jul  9 07:53:33 services: restart needed services and scripts (pppd).
Jul  9 07:53:39 pppd[5507]: Connection terminated.
Jul  9 07:53:39 pppd[5507]: Sent PADT
Jul  9 07:53:39 pppd[5507]: Modem hangup
Jul  9 07:54:19 pppd[5507]: Timeout waiting for PADO packets
Jul  9 07:55:34 pppd[5507]: Timeout waiting for PADO packets
Jul  9 07:56:49 pppd[5507]: Timeout waiting for PADO packets
Jul  9 07:58:04 pppd[5507]: Timeout waiting for PADO packets
Jul  9 07:59:19 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:00:34 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:01:49 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:03:04 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:04:19 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:05:35 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:06:50 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:08:05 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:09:20 pppd[5507]: Timeout waiting for PADO packets
Jul  9 08:09:55 pppd[5507]: PPP session is 1 (0x1)
Jul  9 08:09:55 pppd[5507]: Connected to 08:c6:b3:ce:28:49 via interface eth3
Jul  9 08:09:55 pppd[5507]: Using interface ppp0
Jul  9 08:09:55 pppd[5507]: Connect: ppp0 <--> eth3
Jul  9 08:09:55 pppd[5507]: CHAP authentication succeeded
Jul  9 08:09:55 pppd[5507]: peer from calling number 08:C6:B3:CE:28:49 authorized
Jul  9 08:09:55 pppd[5507]: local  IP address 172.16.200.2
Jul  9 08:09:55 pppd[5507]: remote IP address 172.16.200.1
Jul  9 08:09:55 pppd[5507]: primary   DNS address 192.168.254.1
Jul  9 08:09:55 pppd:up-ppp0: Replace default route to ppp0
Jul  9 08:09:55 pppd:up-ppp0: Flush route cache
Jul  9 08:09:55 pppd:up-ppp0: Restart dns server, dyndns, ntp sync and rebuild shaper and iptables rules
Jul  9 08:09:55 pppd:up-ppp0: Enable forwarding for ppp0 interface
Jul  9 08:09:55 services: restart needed services and scripts (pppd).

По логу видно что клиент "положил трубку" после 10 неудачных посылок lcp_echo.  В том смысле что на них никто не ответил 10 раз с интервалом в 15с.

После чего на всякий послал PADT в сторону браса, сказав что он "устал, он мухожук" и принялся слать PADO с целью узнать кто в сети живой из PPPOE сервеов.

В этом состоянии провисел 10+ минут после чего я кабель со стороны сервера ткнул назад в промежуточный свитч. Буквально через секунду при первом же ответе на PADO клиент снова "дозвонился" до сервера и поднял линк.

У вас же в логе нет даже первой части. Т.е. что-то отвечает на LCP ECHO... Что крайне интересно.

Можно навесить на eth3 (подключившись по ssh со стороны LAN) tcpdump (аля tcpdump -i eth3 -n | grep -i "PPP") после вытыкания кабеля и посмотреть что конкретно у вас происходит в этот момент. Может получится больше инфы нарыть таким образом.

Залил последний сред 3.5.4, перепроверил на > часа интервале.

# cat /var/log/messages | grep -i pppd
Jul  9 09:20:10 pppd[5196]: No response to 10 echo-requests
Jul  9 09:20:10 pppd[5196]: Serial link appears to be disconnected.
Jul  9 09:20:10 pppd[5196]: Connect time 15.1 minutes.
Jul  9 09:20:10 pppd[5196]: Sent 976628 bytes, received 983427 bytes.
Jul  9 09:20:10 pppd:down-ppp0: Disable forwarding for ppp0 interface
Jul  9 09:20:10 pppd:down-ppp0: Restore netfilter rules from pppd
Jul  9 09:20:10 pppd:down-ppp0: Flush route and conntrack cache dev ppp0 172.16.200.3
Jul  9 09:20:10 pppd:down-ppp0: Restart need service and rebuild shaper and iptables rules
Jul  9 09:20:10 services: restart needed services and scripts (pppd).
Jul  9 09:20:16 pppd[5196]: Connection terminated.
Jul  9 09:20:16 pppd[5196]: Sent PADT
Jul  9 09:20:16 pppd[5196]: Modem hangup
Jul  9 09:20:56 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:22:11 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:23:26 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:24:41 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:25:56 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:27:11 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:28:26 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:29:41 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:30:56 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:32:11 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:33:27 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:34:42 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:35:57 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:37:12 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:38:27 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:39:42 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:40:57 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:42:12 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:43:27 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:44:42 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:45:57 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:47:12 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:48:27 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:49:43 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:50:58 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:52:13 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:53:28 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:54:43 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:55:58 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:57:13 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:58:28 pppd[5196]: Timeout waiting for PADO packets
Jul  9 09:59:43 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:00:58 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:02:13 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:03:28 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:04:43 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:05:58 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:07:14 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:08:29 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:09:44 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:10:59 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:12:14 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:13:29 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:14:44 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:15:59 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:17:14 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:18:29 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:19:44 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:20:59 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:22:14 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:23:30 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:24:45 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:26:00 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:27:15 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:28:30 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:29:45 pppd[5196]: Timeout waiting for PADO packets
Jul  9 10:29:45 pppd[5196]: PPP session is 1 (0x1)
Jul  9 10:29:45 pppd[5196]: Connected to 08:c6:b3:ce:28:49 via interface eth3
Jul  9 10:29:45 pppd[5196]: Using interface ppp0
Jul  9 10:29:45 pppd[5196]: Connect: ppp0 <--> eth3
Jul  9 10:29:45 pppd[5196]: CHAP authentication succeeded
Jul  9 10:29:45 pppd[5196]: peer from calling number 08:C6:B3:CE:28:49 authorized
Jul  9 10:29:45 pppd[5196]: local  IP address 172.16.200.2
Jul  9 10:29:45 pppd[5196]: remote IP address 172.16.200.1
Jul  9 10:29:45 pppd[5196]: primary   DNS address 192.168.254.1
Jul  9 10:29:45 pppd:up-ppp0: Replace default route to ppp0
Jul  9 10:29:45 pppd:up-ppp0: Flush route cache
Jul  9 10:29:45 pppd:up-ppp0: Restart dns server, dyndns, ntp sync and rebuild shaper and iptables rules
Jul  9 10:29:45 pppd:up-ppp0: Enable forwarding for ppp0 interface
Jul  9 10:29:45 services: restart needed services and scripts (pppd).

Как видно всё ок. В общем обновляемся, вешаем tcpdump и смотрим. У себя не вижу проблемы ни в каком виде.

Добрый день!

Обновил роутер до 3.5.4.RU.09072021. Заново создал проблемную ситуацию. Поведение изменилось, сессия восстанавливается после потери связи, логи получаются в точности как у вас выше. Но есть частная ситуация, которая снова приходит к "залипанию" статуса сессии.

Если роутер поднял PPPoE сессию до того, как ntpd синхронизировал время (а это обычно так и происходит после "холодного" старта роутера), то он уже не детектирует потерю сессии. Почему-то не шлет и не считает LCP Echo. В веб-интерфейсе сессия вечно висит "online". Приложил логи и конфиг заново.

Если сначала дождаться синхронизации времени на роутере,  после поднять PPPoE вручную в веб-интерфейсе, а потом создать недоступность PPPoE сервера - всё происходит корректно, как описано у вас, сессия восстанавливается роутером через любой промежуток простоя.

Вот это уже интереснее. В pppd есть костыль на эту тему. Проверю не сломали ли его в апстриме.

Похоже нашёл. 2 патчика (апстримный и тот который тащу в ветке с незапамятных времён) подрались. Пол года назад где-то.

В 3.5.5 должно пофикситься. Залью через часик. Просьба проверить и отписаться по результату.

Залил в обновления. Локально проверил, всё ок.

Проверил на стенде с обновленной прошивкой. Все отлично работает. Спасибо!

Отлично. Все бы так репортили давно бы все баги бы были вылечены.

Если вы нашли ошибку, пожалуйста, выделите фрагмент текста и нажмите Ctrl+Enter.

Сообщить об опечатке

Текст, который будет отправлен нашим редакторам: