qzeleza / kvas

vpn и shadowsocks клиент для роутеров keenetic
Other
747 stars 45 forks source link

Не возобновляется маршрутизация после обрыва VPN соединения типа L2TP/IKEv2 #97

Closed wildrun0 closed 5 months ago

wildrun0 commented 9 months ago

Описание проблемы. После обрыва VPN соединения, пропадает маршрутизация ранее добавленных сайтов в квасе.

Информация о системе с которой происходит тестирование пакета на роутере (пожалуйста, заполните следующую информацию):

Информация о роутере (пожалуйста, заполните следующую информацию):

qzeleza commented 9 months ago

Есть ли какая либо информация дополнительная о проблеме?

wildrun0 commented 9 months ago

Все что могу предоставить по теме:

  1. После обрыва и восстановления соединения, не работает маршрутизация
  2. Маршрутизация не работает даже спустя продолжительное время (т.е. я так подозреваю kvas period команда не способна это починить? надо будет уменьшить период и посмотреть)
  3. Маршрутизация возобновляется только после kvas test (надо будет проверить через kvas update?)
qzeleza commented 9 months ago
  • После обрыва и восстановления соединения, не работает маршрутизация

Как Вы понимаете, что соединение восстановлено?

  • Маршрутизация не работает даже спустя продолжительное время (т.е. я так подозреваю kvas period команда не способна это починить? надо будет уменьшить период и посмотреть)

это устаревшая команда

wildrun0 commented 9 months ago

Как Вы понимаете, что соединение восстановлено?

Приложение Keenetic на телефон пишет что vpn отключился/подключился. Так я и узнаю с утра что ночью был разрыв

это устаревшая команда

Пардоньте, не знал. Тогда лучше убрать ее от греха подальше в следующих апдейтах :)

badigit commented 9 months ago

Добрый день, хотел уточнить, здесь под L2TP/IKEv2 подразумевается интерфейс для обхода блокировок, не ISP?

У меня точно такая же проблема в связке stable-2 kvas + adh + Мой провайдер предоставляет WAN подключение по схеме DCHP+L2TP. Так вот, при перезапуске WAN L2TP соединения не восстанавливается обход блокировок (никогда). При ручном выполнении vpn reset все начинает работать.

Написал небольшой скрипт который проверяет обход блокировок раз в минуту на домашнем пк и фиксирует время когда обход перестал работать

#!/bin/bash

while true; do
    # Выполнение traceroute и сохранение вывода в переменную
    output=$(traceroute -m5 telegra.ph)

    # Проверка наличия подстроки IP, через который работает обход блокировок
    if [[ $output == *"94.141.168.245"* ]]; then 
        echo "$(date "+%Y-%m-%d %H:%M:%S"): обход блокировок работает"
    else
        echo "$(date "+%Y-%m-%d %H:%M:%S"): !! Обход блокировок перестал работать!! Ходим по обычному маршруту.."
        exit 1
    fi

    # Ожидание 1 минуту перед следующей итерацией
    sleep 60
done

И могу сопоставить теперь логи роутера с моментом когда обход блокировок перестал работать. Примеры:

Пример 1

26.12 18:49 перестал работать обход блокировок.

В логах кинетика в это время происходит переподключение L2TP WAN соединения (это происходит каждый 1440 минут). [I] Dec 26 18:49:40 pppd_L2TP0: LCP terminated by peer Вот лог кинетика для ознакомления 18-49-disconnect.log

С нерабочим обходом был записан debug выполненный в 26.12 18:56:17, прикладываю debug (2).txt

По дебагу видим ошибки в логах adh, вида 023/12/25 18:50:06.065006 [error] handling tcp: handling tcp request: talking to dns upstream: all upstreams failed to respond:

Примечание1: Может показаться, как будто adh вообще не может достучаться до dns, Но акцентирую что тут не работает только обход блокировок.

Примечание2: в логах adh есть баг?, почему то он показывает разные дни (25 и 26 декабря). На самом деле все было 26 декабря

2023/12/25 18:50:09.256604 [error] 2023/12/26 18:50:07.278464 [error]

Пример 2

Dec 27 03:03 Все похоже с небольшими отличиями - В логах роутера нет явного перезапуска ISP L2TP. Просто мы видим что пошли ретрансмиты на IKE интерфейсе для обхода блокировок и на несколько секунд интернет "моргнул". Видимо что то перезапустилось на оборудовании провайдера. Но этого хватило чтобы обход блокировок отвалился и больше не восстанавливался..

[I] Dec 27 03:00:01 КВАС: Запущен файл /opt/etc/cron.5mins/ipset.kvas
[I] Dec 27 03:01:01 cron[29413]: (root) CMD (/opt/bin/run-parts /opt/etc/cron.hourly^I)
[I] Dec 27 03:02:56 ipsec: 10[IKE] retransmit 1 of request with message ID 0 
[I] Dec 27 03:03:05 ipsec: 05[IKE] retransmit 2 of request with message ID 0 
[I] Dec 27 03:03:14 ipsec: 15[IKE] retransmit 3 of request with message ID 0 
[I] Dec 27 03:03:25 ipsec: 13[IKE] retransmit 4 of request with message ID 0 
[I] Dec 27 03:03:37 ipsec: 07[IKE] retransmit 5 of request with message ID 0 
[I] Dec 27 03:03:44 ndm: Network::Interface::Base: "L2TP0": "ping-check" changed "ipv4" layer state "running" to "pending". 
[I] Dec 27 03:03:45 ndm: Network::InterfaceFlusher: flushed IPv4 L2TP0 conntrack and route cache. 
[I] Dec 27 03:03:45 ndm: Network::InternetChecker: Internet access lost (status: 0x0000). 

debug второго кейса debug3.log

лог кинетика второго кейса log (2).txt

полный лог adh где видны и первый и второй кейс AdGuardHome.log

wildrun0 commented 9 months ago

У меня провайдер (ISP) по IPoE. VPN через ipsec

qzeleza commented 9 months ago

Доброго дня попробуйте после подобной проблемы перезапустить AHG командой kvas adguard restart, потому как по логам явно видно, что AHG просто не может связаться с серверами. Если это решит проблему, то я постараюсь автоматизировать это в Квасе.

badigit commented 9 months ago

Есть ли нужда перезагружать adh? Тест upstream серверов работает и работа dns adh не нарушена. Проблема лечится только переустановкой iptables командой vpn reset.

Похоже adh ругается только на те dns запросы которые ходят через iptables, вот они перестают работать.

qzeleza commented 8 months ago

Есть ли нужда перезагружать adh? Тест upstream серверов работает и работа dns adh не нарушена. Проблема лечится только переустановкой iptables командой vpn reset.

Похоже adh ругается только на те dns запросы которые ходят через iptables, вот они перестают работать.

Какие будут предложения?

badigit commented 8 months ago

выполнять vpn reset по триггерам

после восстановления интернета - событиях типа [I] Dec 27 03:03:45 ndm: Network::InternetChecker: Internet access lost (status: 0x0000). [I] Dec 26 18:49:55 ndm: Network::InternetChecker: Internet access detected. или

[I] Dec 26 18:49:40 ndm: Network::Interface::Base: "L2TP0": "ip" changed "ipv4" layer state "running" to "disabled".

[I] Dec 27 03:04:36 ndm: Network::Interface::Base: "L2TP0": "ping-check" changed "ipv4" layer state "pending" to "running".

и при переподключении VPN интерфейсов, используемых для обхода (проблема о которой говорит wildrun0

qzeleza commented 8 months ago

и при переподключении VPN интерфейсов, используемых для обхода (проблема о которой говорит wildrun0

Есть мысли, как отловить это состояние? В ndm это точно есть?

badigit commented 8 months ago

и при переподключении VPN интерфейсов, используемых для обхода (проблема о которой говорит wildrun0

Есть мысли, как отловить это состояние? В ndm это точно есть?

Не могу сказать, поскольку не обладаю компетенциями по возможностям ndm. Я вижу в логах что квас интенсивно постит туда информацию, вида [I] Dec 27 03:03:48 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Dec 27 03:03:49 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Dec 27 03:03:52 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Dec 27 03:04:36 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО

И это совпадает со временем обрыва L2TP WAN. И это даёт основания предполагать что какие-то похожие триггеры квас отслеживает, значит в ndm что то полезное есть?

qzeleza commented 8 months ago

Обновил пакет до 1.1.7 Проверьте пожалуйста ушла ли проблема?

wildrun0 commented 8 months ago

К сожалению, проблем стало больше - не заходит на сайты из списка. Вообще. ERR_CONNECTION_REFUSED. Пробовал и через разные браузеры, и с очисткой кэша, вообще никак. Причем однажды дало зайти на myip2 и оно показало мой обычный IP, не впн

qzeleza commented 8 months ago

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

wildrun0 commented 8 months ago

debug (2).txt

Да, прошу прощения, не догадался сразу ;)

qzeleza commented 8 months ago

Судя по логу, у Вас "каша" из правил для VPN и SSR. Попробуйте очистить правила и оставить только для конкретного соединения. Если не знаете как, то тогда полностью удалите квас и установите его заново.

badigit commented 8 months ago

Спасибо за обновление, установил, наблюдаю

wildrun0 commented 8 months ago

Переустановил квас заново, все работает. Жду выключеиня впн и дам знать что и как.

badigit commented 8 months ago

В моём случае, автоматического восстановления обхода после перезапуска ISP VPN не произошло. После выполнения debug обход заработал. Есть идеи как отладить?

См. Debug ``` ~ # kvas debug ----------------------------------------------------------------------------------- Версия пакета 1.1.7 ----------------------------------------------------------------------------------- Текущая дата и время Mon Jan 22 14:02:16 +06 2024 ----------------------------------------------------------------------------------- Информация о роутере ----------------------------------------------------------------------------------- Страна: RU Модель: KN-1010 Страна_: EA Тип архитектуры: mipsel Журнал установки пакета: ----------------------------------------------------------------------------------- Текущее VPN соединение: homedi ikev2 (IKE0) AdGuard Home НАСТРОЕН, как основной DNS сервер УСТАНОВЛЕН список разблокировки ПО УМОЛЧАНИЮ. ----------------------------------------------------------------------------------- Установка завершена: 21/01/2024 12:45:38 ----------------------------------------------------------------------------------- Список ошибок из системного журнала ----------------------------------------------------------------------------------- Доступные VPN интерфейсы в системе ----------------------------------------------------------------------------------- shadowsocks = [shadowsocks | shadowsocks] homedi ikev2 = [IKE0 | homedi ikev2] ----------------------------------------------------------------------------------- ----------------------------------------------------------------------------------- Блок записей по ipset в /opt/etc/AdGuardHome/kvas.ipset ----------------------------------------------------------------------------------- 2ip.ru/unblock ag-vmeste.ru/unblock astralnalog.ru/unblock beeline.ru/unblock bit.ly/unblock comss.ru/unblock crediteurope.ru/unblock gosuslugi.ru/unblock livejournal.com/unblock livejournal.net/unblock mediafire.com/unblock megapbx.ru/unblock memepedia.ru/unblock mgfoms.ru/unblock microsoftonline.com/unblock moderators.pro/unblock mos.ru/unblock mosenergosbyt.ru/unblock novofon.com/unblock onlinetrade.ru/unblock otpbank.ru/unblock pinterest.com/unblock pochta.ru/unblock sprinthost.ru/unblock telegra.ph/unblock tripadvisor.ru/unblock zadarma.com/unblock myip.ru/unblock myip.ru/unblock myip2.ru/unblock ----------------------------------------------------------------------------------- Журнал загрузки AdGuard Home в /opt/var/log/AdGuardHome.log ----------------------------------------------------------------------------------- 2024/01/21 13:32:51.092969 [info] dnsproxy: starting dns proxy server 2024/01/21 13:32:51.093285 [info] clients: processing addresses 2024/01/21 13:32:51.093350 [info] Cache TTL override is enabled. Min=200, Max=25000 2024/01/21 13:32:51.093837 [info] Ratelimit is enabled and set to 100 rps 2024/01/21 13:32:51.094081 [info] The server is configured to refuse ANY requests 2024/01/21 13:32:51.094218 [info] dnsproxy: cache: enabled, size 4194304 b 2024/01/21 13:32:51.094437 [info] dnsproxy: max goroutines is set to 300 2024/01/21 13:32:51.094681 [info] dnsproxy: creating udp server socket 0.0.0.0:53 2024/01/21 13:32:51.095239 [info] dnsproxy: listening to udp://[::]:53 2024/01/21 13:32:51.095383 [info] dnsproxy: creating udp server socket 127.0.0.1:53 2024/01/21 13:32:51.095785 [info] dnsproxy: listening to udp://127.0.0.1:53 2024/01/21 13:32:51.095937 [info] dnsproxy: creating tcp server socket 0.0.0.0:53 2024/01/21 13:32:51.096312 [info] dnsproxy: listening to tcp://[::]:53 2024/01/21 13:32:51.096448 [info] dnsproxy: creating tcp server socket 127.0.0.1:53 2024/01/21 13:32:51.096757 [info] dnsproxy: listening to tcp://127.0.0.1:53 2024/01/21 13:32:51.097084 [info] dnsforward: finished reconfiguring server 2024/01/21 13:32:51.097284 [info] dnsproxy: entering udp listener loop on [::]:53 2024/01/21 13:32:51.097700 [info] dnsproxy: entering tcp listener loop on 127.0.0.1:53 2024/01/21 13:32:51.097285 [info] dnsproxy: entering tcp listener loop on [::]:53 2024/01/21 13:32:51.097313 [info] dnsproxy: entering udp listener loop on 127.0.0.1:53 ----------------------------------------------------------------------------------- Состояние vpn соединения homedi ikev2 ПОДКЛЮЧЕНО ----------------------------------------------------------------------------------- Таблица правил маршрутизации VPN списка id=1001 команда: 'ip rule show' ----------------------------------------------------------------------------------- 0: from all lookup local 10: from all fwmark 0xffffcff lookup main 400: from 10.199.12.174 lookup 58 401: from 10.27.8.234 lookup 59 500: from all lookup 248 1778: from all fwmark 0xd1000/0xd1000 lookup 1001 32766: from all lookup main 32767: from all lookup default ----------------------------------------------------------------------------------- Переустановка iptables для vpn завершена УСПЕШНО ----------------------------------------------------------------------------------- Правила перенаправления трафика unblock в iptables команда: iptables-save | grep -E 'SHADOWSOCKS|VPNREDIR|unblock' ----------------------------------------------------------------------------------- :VPNREDIR - [0:0] -A PREROUTING -p tcp -m set --match-set unblock dst -j VPNREDIR -A PREROUTING -p udp -m set --match-set unblock dst -j VPNREDIR -A OUTPUT -p tcp -m set --match-set unblock dst -j VPNREDIR -A OUTPUT -p udp -m set --match-set unblock dst -j VPNREDIR -A VPNREDIR -m set ! --match-set unblock dst -j RETURN -A VPNREDIR -d 0.0.0.0/8 -j RETURN -A VPNREDIR -d 127.0.0.0/8 -j RETURN -A VPNREDIR -d 10.0.0.0/8 -j RETURN -A VPNREDIR -d 169.254.0.0/16 -j RETURN -A VPNREDIR -d 172.16.0.0/12 -j RETURN -A VPNREDIR -d 192.168.0.0/16 -j RETURN -A VPNREDIR -d 224.0.0.0/4 -j RETURN -A VPNREDIR -d 240.0.0.0/4 -j RETURN -A VPNREDIR -j CONNMARK --restore-mark --nfmask 0xffffffff --ctmask 0xffffffff -A VPNREDIR -m mark --mark 0xd1000 -j RETURN -A VPNREDIR -p tcp -m tcp --tcp-flags FIN,SYN,RST,ACK SYN -j MARK --set-xmark 0xd1000/0xffffffff -A VPNREDIR -p udp -m conntrack --ctstate NEW -j MARK --set-xmark 0xd1000/0xffffffff -A VPNREDIR -j CONNMARK --save-mark --nfmask 0xffffffff --ctmask 0xffffffff ----------------------------------------------------------------------------------- Список разблокировки /opt/etc/hosts.list (все записи) ----------------------------------------------------------------------------------- 2ip.ru ag-vmeste.ru astralnalog.ru beeline.ru bit.ly comss.ru crediteurope.ru gosuslugi.ru livejournal.com livejournal.net mediafire.com megapbx.ru memepedia.ru mgfoms.ru microsoftonline.com moderators.pro mos.ru mosenergosbyt.ru myip.ru myip2.ru novofon.com onlinetrade.ru otpbank.ru pinterest.com pochta.ru sprinthost.ru telegra.ph tripadvisor.ru zadarma.com ----------------------------------------------------------------------------------- DNS сервер, используемый в /opt/apps/kvas/bin/main/ipset ----------------------------------------------------------------------------------- @127.0.0.1:53 ----------------------------------------------------------------------------------- Таблица ipset (все записи) команда: 'ipset list unblock' ----------------------------------------------------------------------------------- 104.16.113.74 104.16.114.74 104.21.23.71 109.207.1.118 109.207.1.47 109.207.1.97 109.207.2.205 109.207.8.118 109.207.8.97 109.207.9.205 141.8.197.25 141.8.197.26 141.8.197.6 141.8.197.99 149.154.164.13 151.101.0.84 151.101.128.84 151.101.130.28 151.101.192.84 151.101.194.28 151.101.2.28 151.101.64.84 151.101.66.28 172.66.40.144 172.66.43.112 172.67.209.126 178.176.128.128 178.62.9.171 185.129.100.112 185.169.155.27 185.45.153.82 185.45.153.83 185.71.67.129 185.71.67.160 188.114.98.229 188.114.99.229 193.201.230.160 195.133.255.86 195.14.106.70 195.201.201.35 195.82.140.164 199.232.148.84 20.190.163.19 20.190.163.20 20.190.163.21 212.11.151.56 212.11.151.57 212.11.151.58 212.164.138.77 212.164.138.79 213.59.253.21 213.59.253.7 213.59.254.7 213.59.254.8 217.118.87.98 31.31.222.204 37.139.38.156 40.126.35.144 40.126.35.150 40.126.35.151 40.126.35.18 40.126.35.19 40.126.35.20 40.126.35.21 40.126.35.64 40.126.35.80 40.126.35.86 40.126.35.87 67.199.248.10 67.199.248.11 81.19.74.0 81.19.74.1 81.90.181.105 94.79.51.12 94.79.51.13 94.79.51.14 ----------------------------------------------------------------------------------- Проверка наличия ip адресов хостов в таблице ipset команда 'ipset list unblock' ----------------------------------------------------------------------------------- 2ip.ru --> 195.201.201.35 В ТАБЛИЦЕ ag-vmeste.ru --> 94.79.51.14|94.79.51.12|94.79.51.13 В ТАБЛИЦЕ astralnalog.ru --> 185.71.67.129 В ТАБЛИЦЕ beeline.ru --> 217.118.87.98 В ТАБЛИЦЕ bit.ly --> 67.199.248.10|67.199.248.11 В ТАБЛИЦЕ comss.ru --> 172.66.40.144|172.66.43.112 В ТАБЛИЦЕ crediteurope.ru --> 195.14.106.70 В ТАБЛИЦЕ gosuslugi.ru --> 213.59.253.7|213.59.254.7 В ТАБЛИЦЕ livejournal.com --> 81.19.74.0|81.19.74.1 В ТАБЛИЦЕ livejournal.net АДРЕСА НЕТ mediafire.com --> 104.16.113.74|104.16.114.74 В ТАБЛИЦЕ megapbx.ru --> 193.201.230.160 В ТАБЛИЦЕ memepedia.ru --> 172.67.209.126|104.21.23.71 В ТАБЛИЦЕ mgfoms.ru --> 195.133.255.86 В ТАБЛИЦЕ microsoftonline.com АДРЕСА НЕТ moderators.pro --> 185.129.100.112 В ТАБЛИЦЕ mos.ru --> 94.79.51.13 В ТАБЛИЦЕ mosenergosbyt.ru --> 195.82.140.164 В ТАБЛИЦЕ myip.ru --> 178.62.9.171 В ТАБЛИЦЕ myip2.ru --> 81.90.181.105 В ТАБЛИЦЕ novofon.com --> 37.139.38.156 В ТАБЛИЦЕ onlinetrade.ru --> 185.169.155.27 В ТАБЛИЦЕ otpbank.ru --> 185.71.67.160 В ТАБЛИЦЕ pinterest.com --> 151.101.0.84|151.101.128.84|151.101.64.84|151.... В ТАБЛИЦЕ pochta.ru --> 212.164.138.77|212.164.138.79 В ТАБЛИЦЕ sprinthost.ru --> 141.8.197.26|141.8.197.6|141.8.197.99|141.8.197.25 В ТАБЛИЦЕ telegra.ph --> 149.154.164.13 В ТАБЛИЦЕ tripadvisor.ru --> 151.101.130.28|151.101.2.28|151.101.66.28|151... В ТАБЛИЦЕ zadarma.com --> 31.31.222.204 В ТАБЛИЦЕ ----------------------------------------------------------------------------------- ```
qzeleza commented 8 months ago

В моём случае, автоматического восстановления обхода после перезапуска ISP VPN не произошло. После выполнения debug обход заработал. Есть идеи как отладить?

Подумаю, чуть позже выложу решение.

badigit commented 8 months ago

Как вариант, можно было бы добавить отладки в лог роутера, чтобы было видно, поймал ли "квас" момент перезапуска соединения

qzeleza commented 8 months ago

В моём случае, автоматического восстановления обхода после перезапуска ISP VPN не произошло. После выполнения debug обход заработал. Есть идеи как отладить?

Подскажите какая версия OS на роутере у Вас установлена?

badigit commented 8 months ago

4.0.7

qzeleza commented 8 months ago

тогда код следующий открываем файл /opt/etc/ndm/iflayerchanged.d/test.sh

#!/bin/sh
if [ "${1}" = "hook" ] && [[ ${id} =~ 'PPTP|L2TP' ]]; then
        # Отслеживаем, когда подключается к провайдеру через соединения типа PPTP или L2TP
        [ "${layer}-${level}" = "ctrl-running" ] && {
            logger -t "КВАС:проверка"  "Соединение ${id}::${system_name} успешно подключено."
        }
        [ "${layer}-${level}" = "ctrl-disabled" ] && {
            logger -t "КВАС:проверка"  "Соединение ${id}::${system_name}  успешно завершено."
        }
fi

далее, даем права на выполнение

wildrun0 commented 8 months ago

Разрыв был 3ч назад, маршрутизация не поднялась. Прикладываю дебаг, если чем сможет помочь: conn_term.txt

badigit commented 8 months ago

тогда код следующий

Добавил скрипт, и протестировал перезагрузку соединения. Вот результат

вот лог кинетика ``` [I] Jan 23 21:34:32 pppd_L2TP0: Modem hangup [I] Jan 23 21:34:32 pppd_L2TP0: Connect time 1170.8 minutes. [I] Jan 23 21:34:32 pppd_L2TP0: Sent 2822105568 bytes, received 1653062484 bytes. [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "running" to "pending". [I] Jan 23 21:34:32 ndm: Network::Interface::Ppp: "L2TP0": connection service standby. [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "pending" to "running". [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "base" changed "conf" layer state "running" to "disabled". [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": interface is down. [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "base" changed "conf" layer state "disabled" to "running". [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 23 21:34:32 pppd_L2TP0: Connection terminated. [I] Jan 23 21:34:32 pppd_L2TP0: l2tp: shutting down control connection [I] Jan 23 21:34:32 pppd_L2TP0: l2tp: sending cdn [I] Jan 23 21:34:32 pppd_L2TP0: l2tp: sending stopccn [I] Jan 23 21:34:32 pppd_L2TP0: l2tp: recv [CTRL ZLB ] [I] Jan 23 21:34:32 pppd_L2TP0: l2tp: recv [CTRL ZLB ] [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "ip" changed "ipv4" layer state "running" to "disabled". [I] Jan 23 21:34:32 ndm: Network::Interface::Ip: "L2TP0": IP address cleared. [I] Jan 23 21:34:32 pppd_L2TP0: Exit. [I] Jan 23 21:34:32 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "running" to "connecting". [I] Jan 23 21:34:33 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "running" to "pending". [E] Jan 23 21:34:33 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:33 ndm: Dns::Manager: name server 5.34.34.5 added, domain (default). [I] Jan 23 21:34:33 ndm: Dns::Manager: name server 37.99.99.37 added, domain (default). [I] Jan 23 21:34:33 ndhcpc: GigabitEthernet1: received ACK for 10.27.8.234 from 87.247.0.130 lease 86000 sec. [E] Jan 23 21:34:33 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:33 ndm: Network::Interface::PppTunnel: "L2TP0": interface state is changed, reconnecting. [I] Jan 23 21:34:33 ndm: Network::Interface::L2tp: "L2TP0": interface is down. [I] Jan 23 21:34:33 ndm: Network::Interface::PppTunnel: "L2TP0": interface state is changed, reconnecting. [I] Jan 23 21:34:33 ndm: Network::Interface::PppTunnel: "L2TP0": try to resolve remote endpoint via 5.34.34.5. [I] Jan 23 21:34:33 ndm: Dns::Manager: name server 5.34.34.5 added, domain (default). [I] Jan 23 21:34:33 ndm: Dns::Manager: name server 37.99.99.37 added, domain (default). [E] Jan 23 21:34:33 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [E] Jan 23 21:34:33 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:33 ndm: Network::InterfaceFlusher: flushed IPv4 L2TP0 conntrack and route cache. [I] Jan 23 21:34:33 ndm: Network::InternetChecker: Internet access lost (status: 0x0000). [I] Jan 23 21:34:33 upnp: shutting down MiniUPnPd [I] Jan 23 21:34:33 ndm: Core::Session: client disconnected. [E] Jan 23 21:34:33 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:33 ndm: Http::Nginx: loaded SSL certificate for "bccd74bf91143d950a5beea9.keenetic.io". [I] Jan 23 21:34:34 ndm: Http::Nginx: loaded SSL certificate for "amaltea.keenetic.pro". [I] Jan 23 21:34:34 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:34 ndm: Core::Session: client disconnected. [I] Jan 23 21:34:34 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: line 24: cmd_vpn_iptable_reset: not found. [I] Jan 23 21:34:34 КВАС: Соединение L2TP0 успешно подключено. [I] Jan 23 21:34:34 КВАС: �роверка: Соединение L2TP0::ppp0 успешно подключено. [E] Jan 23 21:34:34 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:34 КВАС: �роверка: Соединение L2TP0::ppp0 успешно завершено. [I] Jan 23 21:34:34 ndm: Http::Manager: updated configuration. [I] Jan 23 21:34:34 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:34 ndm: Core::Session: client disconnected. [I] Jan 23 21:34:34 ndm: Network::Interface::Ip: "L2TP0": removing default route via L2TP0. [I] Jan 23 21:34:34 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 23 21:34:34 ndm: Network::Interface::PppTunnel: "L2TP0": try to resolve remote endpoint via 5.34.34.5. [E] Jan 23 21:34:34 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:34 ndm: Network::InterfaceFlusher: flushed IPv4 GigabitEthernet1 conntrack and route cache. [E] Jan 23 21:34:34 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:34 pppd_L2TP0: l2tp: shutdown completed [I] Jan 23 21:34:34 ndm: Network::InterfaceFlusher: flushed IPv4 L2TP0 conntrack and route cache. [E] Jan 23 21:34:34 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [E] Jan 23 21:34:35 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:35 ndm: Network::InterfaceFlusher: flushed IPv4 GigabitEthernet1 conntrack and route cache. [E] Jan 23 21:34:35 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:35 ndm: Network::InterfaceFlusher: flushed IPv4 L2TP0 conntrack and route cache. [E] Jan 23 21:34:35 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:35 ndm: Network::Interface::EndpointTracker: "L2TP0": remote endpoint is "80.241.35.115". [I] Jan 23 21:34:35 ndm: Network::Interface::EndpointTracker: "L2TP0": connecting via ISP (GigabitEthernet1). [I] Jan 23 21:34:35 ndm: Network::Interface::EndpointTracker: "L2TP0": local endpoint is "10.27.8.234". [I] Jan 23 21:34:35 ndm: Network::Interface::EndpointTracker: "L2TP0": added a host route to 80.241.35.115 via 10.27.8.1 (GigabitEthernet1). [I] Jan 23 21:34:35 ndm: Network::Interface::L2tp: "L2TP0": using port 1701 as local. [I] Jan 23 21:34:35 ndm: Network::Interface::Ppp: "L2TP0": enabled connection via GigabitEthernet1 interface. [E] Jan 23 21:34:35 coalagent: [SecLayer_OnSend] Coala_Send: Network unreachable. [I] Jan 23 21:34:35 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: line 24: cmd_vpn_iptable_reset: not found. [I] Jan 23 21:34:35 КВАС: Соединение L2TP0 успешно подключено. [I] Jan 23 21:34:35 КВАС: �роверка: Соединение L2TP0::ppp0 успешно подключено. [I] Jan 23 21:34:36 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [W] Jan 23 21:34:36 ndm: Process: "Dhcp::Client-IKE0" has been killed. [E] Jan 23 21:34:36 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [E] Jan 23 21:34:37 ndm: Core::Syslog: last message repeated 2 times. [I] Jan 23 21:34:37 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:37 upnp: HTTP listening on port 1900 [I] Jan 23 21:34:37 upnp: Listening for NAT-PMP/PCP traffic on port 5351 [I] Jan 23 21:34:37 l2tp[24133]: Plugin pppol2tp.so loaded. [I] Jan 23 21:34:37 l2tp[24133]: pppd 2.4.4-4 started by root, uid 0 [I] Jan 23 21:34:37 ndm: Network::Interface::EndpointTracker: "L2TP0": added a host route to 80.241.35.115 via 10.27.8.1 (GigabitEthernet1). [I] Jan 23 21:34:37 pppd_L2TP0: l2tp_control v2.02 [I] Jan 23 21:34:37 pppd_L2TP0: remote host: 80.241.35.115:1701 [I] Jan 23 21:34:37 pppd_L2TP0: local bind: 10.27.8.234:1701 [I] Jan 23 21:34:38 pppd_L2TP0: creating in-kernel L2TP tunnel (R/L 58307/29935) [I] Jan 23 21:34:38 pppd_L2TP0: creating in-kernel L2TP session (R/L 22824/32035) [I] Jan 23 21:34:38 pppd_L2TP0: L2TP tunnel/session created [I] Jan 23 21:34:38 pppd_L2TP0: PPP channel connected [I] Jan 23 21:34:38 pppd_L2TP0: Using interface ppp0 [I] Jan 23 21:34:38 pppd_L2TP0: Connect: ppp0 <--> l2tp[0] [I] Jan 23 21:34:38 ndm: Network::Interface::Tunnel4: "IKE0": resolved destination 94.141.168.245 (homedi.keenetic.pro). [I] Jan 23 21:34:38 ndm: Network::Interface::Tunnel4: "IKE0": use interface GigabitEthernet1 as source. [I] Jan 23 21:34:38 pppd_L2TP0: PAP authentication succeeded [I] Jan 23 21:34:38 ndm: Network::Interface::Ip: "IKE0": IP address cleared. [I] Jan 23 21:34:38 ndm: Network::Interface::Tunnel4: "IKE0": resolved source 10.27.8.234. [I] Jan 23 21:34:38 pppd_L2TP0: local IP address 10.196.40.95 [I] Jan 23 21:34:38 pppd_L2TP0: remote IP address 80.241.35.115 [I] Jan 23 21:34:38 pppd_L2TP0: primary DNS address 5.34.34.5 [I] Jan 23 21:34:38 pppd_L2TP0: secondary DNS address 37.99.99.37 [I] Jan 23 21:34:38 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "pending" to "running". [I] Jan 23 21:34:38 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 23 21:34:38 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: tcp. [I] Jan 23 21:34:38 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 23 21:34:38 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 23 21:34:38 ndm: Network::Interface::Ip: "L2TP0": interface "L2TP0" is global, priority 53268. [I] Jan 23 21:34:38 ndm: Network::Interface::Ip: "L2TP0": adding default route via L2TP0. [I] Jan 23 21:34:38 ndm: Dns::InterfaceSpecific: adding name server 5.34.34.5. [I] Jan 23 21:34:38 ndm: Dns::InterfaceSpecific: "L2TP0": name server 5.34.34.5 added, domain (default). [I] Jan 23 21:34:38 ndm: Dns::InterfaceSpecific: adding name server 37.99.99.37. [I] Jan 23 21:34:38 ndm: Dns::InterfaceSpecific: "L2TP0": name server 37.99.99.37 added, domain (default). [I] Jan 23 21:34:38 ndm: Network::Interface::Ip: "L2TP0": IP address is 10.196.40.95/32. [I] Jan 23 21:34:38 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 23 21:34:38 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: udp. [I] Jan 23 21:34:38 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "connecting" to "running". [I] Jan 23 21:34:38 ndm: Network::Interface::Tunnel4: "IKE0": added host route to tunnel destination endpoint 94.141.168.245 via 10.27.8.1. [I] Jan 23 21:34:38 ndm: Network::Interface::Secure: "IKE0": updating server IP secure configuration #248. [I] Jan 23 21:34:38 ndm: Dns::Manager: name server 5.34.34.5 added, domain (default). [I] Jan 23 21:34:38 ndm: Dns::Manager: name server 37.99.99.37 added, domain (default). [I] Jan 23 21:34:39 ndm: Http::Nginx: loaded SSL certificate for "bccd74bf91143d950a5beea9.keenetic.io". [I] Jan 23 21:34:39 ndm: Http::Nginx: loaded SSL certificate for "amaltea.keenetic.pro". [I] Jan 23 21:34:39 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:39 ndm: Core::Session: client disconnected. [I] Jan 23 21:34:39 ndm: Http::Manager: updated configuration. [I] Jan 23 21:34:39 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 23 21:34:39 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:39 ndm: Core::Session: client disconnected. [I] Jan 23 21:34:39 ndm: IpSec::Apply: "IKE0": IP secure connection and keys was deleted #248. [I] Jan 23 21:34:39 ndm: IpSec::Apply: "IKE0": IP secure connection was added #248. [I] Jan 23 21:34:39 ndm: IpSec::Manager: "IKE0": reinitiate IP secure #248. [I] Jan 23 21:34:40 ndm: Network::InterfaceFlusher: flushed IPv4 GigabitEthernet1 conntrack and route cache. [I] Jan 23 21:34:40 upnp: shutting down MiniUPnPd [I] Jan 23 21:34:40 ndm: Core::Session: client disconnected. [I] Jan 23 21:34:40 ndm: Network::InternetChecker: Internet access detected. [I] Jan 23 21:34:40 ndhcpc: IKE0: NDM DHCP Client, v3.2.53. [I] Jan 23 21:34:40 ndhcpc: IKE0: created PID file "/var/run/ndhcpc-nikecli0.pid". [I] Jan 23 21:34:41 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "running" to "pending". [I] Jan 23 21:34:41 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 23 21:34:41 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: tcp. [I] Jan 23 21:34:41 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 23 21:34:41 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: udp. [I] Jan 23 21:34:42 ndm: Network::Interface::Tunnel4: "IKE0": resolved destination 94.141.168.245 (homedi.keenetic.pro). [I] Jan 23 21:34:42 ndm: Network::Interface::Tunnel4: "IKE0": use interface L2TP0 as source. [I] Jan 23 21:34:42 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 23 21:34:42 ndm: Network::Interface::Ip: "IKE0": IP address cleared. [I] Jan 23 21:34:42 ndm: Network::Interface::Tunnel4: "IKE0": resolved source 10.196.40.95. [I] Jan 23 21:34:42 upnp: HTTP listening on port 1900 [I] Jan 23 21:34:42 upnp: Listening for NAT-PMP/PCP traffic on port 5351 [I] Jan 23 21:34:42 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "pending" to "running". [I] Jan 23 21:34:42 ndm: Network::Interface::Tunnel4: "IKE0": added host route to tunnel destination endpoint 94.141.168.245 via L2TP0. [I] Jan 23 21:34:42 ndm: Network::Interface::Secure: "IKE0": updating server IP secure configuration #249. [I] Jan 23 21:34:42 ndm: IpSec::Apply: "IKE0": IP secure connection and keys was deleted #249. [I] Jan 23 21:34:42 ndm: IpSec::Apply: "IKE0": IP secure connection was added #249. [I] Jan 23 21:34:42 ndm: IpSec::Manager: "IKE0": reinitiate IP secure #249. [W] Jan 23 21:34:43 ndm: Process: "Dhcp::Client-IKE0" has been killed. [I] Jan 23 21:34:45 ndhcpc: IKE0: NDM DHCP Client, v3.2.53. [I] Jan 23 21:34:45 ndhcpc: IKE0: created PID file "/var/run/ndhcpc-nikecli0.pid". [E] Jan 23 21:34:48 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [E] Jan 23 21:34:48 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 23 21:34:48 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: line 24: cmd_vpn_iptable_reset: not found. [I] Jan 23 21:34:48 КВАС: Соединение L2TP0 успешно подключено. [I] Jan 23 21:34:48 КВАС: �роверка: Соединение L2TP0::ppp0 успешно подключено. [I] Jan 23 21:34:50 ndm: Network::Interface::Mtk::WifiMonitor: "WifiMaster1/AccessPoint0": STA(64:5a:36:34:b6:44) had associated (has FT caps). [I] Jan 23 21:34:50 ndm: Network::Interface::Mtk::WifiMonitor: "WifiMaster1/AccessPoint0": STA(64:5a:36:34:b6:44) set key done in WPA2/WPA2PSK. [I] Jan 23 21:34:50 ndhcps: DHCPREQUEST received (STATE_INIT) for 10.9.8.77 from 64:5a:36:34:b6:44. [I] Jan 23 21:34:51 ndhcps: sending ACK of 10.9.8.77 to 64:5a:36:34:b6:44. [I] Jan 23 21:34:51 ndhcps: DHCPREQUEST received (STATE_INIT) for 10.9.8.77 from 64:5a:36:34:b6:44. [E] Jan 23 21:34:51 ndhcpc: IKE0: can not send INFORM from interface nikecli0 with IP address 0.0.0.0. [I] Jan 23 21:34:51 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 23 21:34:51 ndhcps: sending ACK of 10.9.8.77 to 64:5a:36:34:b6:44. ```

Что я вижу:

  1. Ошибка kvas-ips-reset kvas-ips-reset: exit code 1. kvas-ips-reset: line 24: cmd_vpn_iptable_reset: not found.
  1. Странный порядок. в журнале. - сначала подключено потом завершено в одну секунду, хотя по логам завершено.. Соединение L2TP0 успешно подключено. Соединение L2TP0::ppp0 успешно подключено. Соединение L2TP0::ppp0 успешно завершено.

Видимо нужно учитывать в скрипте..

  1. Восстановление соединения тоже есть Соединение L2TP0::ppp0 успешно подключено. Соединение L2TP0::ppp0 успешно завершено.

  2. Важный момент - VPN для обхода поднимается не сразу, он восстановился только спустя 2 минуты. А значит до этого времени даже vpn reset пользы бы не принес... [I] Jan 23 21:36:51 ndm: IpSec::Interface::Ike: "IKE0": secured tunnel is ready.

qzeleza commented 8 months ago

Полагаю, что проблема в отсутствии функции cmd_vpn_iptable_reset Завтра выложу исправление.

он восстановился только спустя 2 минуты.

Разве? По моему лог посекундный, нет?

badigit commented 8 months ago

Посекундный, но разница 2 минуты, просто я не весь лог выложил восстановление L2TP 21:34:35 Восстановление ipsec 21:36:51 между ними - попытки подключиться к ipsec. Закину этот вопрос в поддержку кинетиков. Что то долго кинетик не может поднять ipsec к другому кинетику..

qzeleza commented 8 months ago

Полагаю, что проблема в отсутствии функции cmd_vpn_iptable_reseta

Не успеваю сегодня выпустить обновление, попробуйте в файле /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset в одной из первых строчек заменить имя подгружаемой библиотеки: вместо main необходимо поменять на vpn.

qzeleza commented 8 months ago

Исправил - попробуйте продиагностировать.

badigit commented 8 months ago

Не сработало... [E] Jan 25 21:34:46 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1.

Лог кинетика

``` [I] Jan 25 21:34:45 pppd_L2TP0: LCP terminated by peer [I] Jan 25 21:34:45 pppd_L2TP0: Connect time 1440.1 minutes. [I] Jan 25 21:34:45 pppd_L2TP0: Sent 2859686149 bytes, received 3849441185 bytes. [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: recv CDN [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: RC = 2 - Call disconnected for the reason indicated in error code [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: EC = 6 - A generic vendor-specific error occurred in the LAC [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: EM: "Session Timeout" [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: shutting down control connection [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: sending stopccn [I] Jan 25 21:34:45 pppd_L2TP0: l2tp: recv [CTRL ZLB ] [I] Jan 25 21:34:45 ndm: Network::Interface::Base: "L2TP0": "ip" changed "ipv4" layer state "running" to "disabled". [I] Jan 25 21:34:45 ndm: Network::Interface::Ip: "L2TP0": IP address cleared. [I] Jan 25 21:34:46 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "running" to "connecting". [I] Jan 25 21:34:46 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "running" to "pending". [I] Jan 25 21:34:46 ndm: Network::InterfaceFlusher: flushed IPv4 L2TP0 conntrack and route cache. [I] Jan 25 21:34:46 ndm: Network::InternetChecker: Internet access lost (status: 0x0000). [I] Jan 25 21:34:46 upnp: shutting down MiniUPnPd [I] Jan 25 21:34:46 ndm: Core::Session: client disconnected. [E] Jan 25 21:34:46 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 25 21:34:46 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 25 21:34:46 ndhcpc: GigabitEthernet1: received ACK for 10.27.8.234 from 87.247.0.130 lease 86000 sec. [E] Jan 25 21:34:46 coalagent: [SecLayer_OnSend] Coala_Send: Network unreachable. [I] Jan 25 21:34:46 ndm: Http::Nginx: loaded SSL certificate for "bccd74bf91143d950a5beea9.keenetic.io". [I] Jan 25 21:34:46 ndm: Http::Nginx: loaded SSL certificate for "amaltea.keenetic.pro". [I] Jan 25 21:34:47 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:47 ndm: Core::Session: client disconnected. [E] Jan 25 21:34:47 ndm: Opkg::Manager: /opt/etc/ndm/netfilter.d/100-vpn-mark: exit code 2. [I] Jan 25 21:34:47 ndm: Http::Manager: updated configuration. [I] Jan 25 21:34:47 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:47 ndm: Core::Session: client disconnected. [E] Jan 25 21:34:47 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [E] Jan 25 21:34:47 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 25 21:34:47 pppd_L2TP0: l2tp: shutdown completed [I] Jan 25 21:34:47 pppd_L2TP0: Hangup (SIGHUP) [I] Jan 25 21:34:48 ndm: Network::Interface::Tunnel4: "IKE0": resolved destination 94.141.168.245 (homedi.keenetic.pro). [I] Jan 25 21:34:48 ndm: Network::Interface::Tunnel4: "IKE0": use interface GigabitEthernet1 as source. [I] Jan 25 21:34:48 ndm: Network::Interface::Ip: "IKE0": IP address cleared. [I] Jan 25 21:34:48 ndm: Network::Interface::Tunnel4: "IKE0": resolved source 10.27.8.234. [I] Jan 25 21:34:48 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:48 upnp: HTTP listening on port 1900 [I] Jan 25 21:34:48 upnp: Listening for NAT-PMP/PCP traffic on port 5351 [W] Jan 25 21:34:48 ndm: Process: "Dhcp::Client-IKE0" has been killed. [I] Jan 25 21:34:48 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 25 21:34:48 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: tcp. [I] Jan 25 21:34:48 КВАС: Подключаем правила для корректной работы DNS трафика через 53 порт: [I] Jan 25 21:34:48 КВАС: Интерфейс: br0, IP: 10.9.8.1, протокол: udp. [I] Jan 25 21:34:48 ndm: Network::Interface::Base: "IKE0": "tunnel" changed "link" layer state "pending" to "running". [I] Jan 25 21:34:48 ndm: Network::Interface::Tunnel4: "IKE0": added host route to tunnel destination endpoint 94.141.168.245 via 10.27.8.1. [I] Jan 25 21:34:48 ndm: Network::Interface::Secure: "IKE0": updating server IP secure configuration #279. [I] Jan 25 21:34:48 pppd_L2TP0: Connection terminated. [E] Jan 25 21:34:48 pppd_L2TP0: write: Bad file descriptor (9) [I] Jan 25 21:34:48 pppd_L2TP0: Modem hangup [E] Jan 25 21:34:48 pppd_L2TP0: write: Bad file descriptor (9) [I] Jan 25 21:34:48 pppd_L2TP0: Exit. [E] Jan 25 21:34:48 ndm: Service: "L2TP0": unexpectedly stopped. [I] Jan 25 21:34:48 ndm: IpSec::Apply: "IKE0": IP secure connection and keys was deleted #279. [I] Jan 25 21:34:48 ndm: IpSec::Apply: "IKE0": IP secure connection was added #279. [I] Jan 25 21:34:48 ndm: IpSec::Manager: "IKE0": reinitiate IP secure #279. [I] Jan 25 21:34:48 ndm: Network::Interface::Ip: "L2TP0": removing default route via L2TP0. [I] Jan 25 21:34:48 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 25 21:34:48 ndm: Network::Interface::PppTunnel: "L2TP0": try to resolve remote endpoint via 5.34.34.5. [I] Jan 25 21:34:49 ndm: Http::Nginx: loaded SSL certificate for "bccd74bf91143d950a5beea9.keenetic.io". [I] Jan 25 21:34:49 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 25 21:34:49 ndm: Http::Nginx: loaded SSL certificate for "amaltea.keenetic.pro". [I] Jan 25 21:34:49 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:49 ndm: Core::Session: client disconnected. [I] Jan 25 21:34:49 ndm: Http::Manager: updated configuration. [I] Jan 25 21:34:49 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:49 ndm: Core::Session: client disconnected. [I] Jan 25 21:34:49 ndm: Network::Interface::EndpointTracker: "L2TP0": remote endpoint is "80.241.35.38". [I] Jan 25 21:34:49 ndm: Network::Interface::EndpointTracker: "L2TP0": connecting via ISP (GigabitEthernet1). [I] Jan 25 21:34:49 ndm: Network::Interface::EndpointTracker: "L2TP0": local endpoint is "10.27.8.234". [I] Jan 25 21:34:49 ndm: Network::Interface::EndpointTracker: "L2TP0": added a host route to 80.241.35.38 via 10.27.8.1 (GigabitEthernet1). [I] Jan 25 21:34:49 ndm: Network::Interface::L2tp: "L2TP0": using port 1701 as local. [I] Jan 25 21:34:49 ndm: Network::Interface::Ppp: "L2TP0": enabled connection via GigabitEthernet1 interface. [E] Jan 25 21:34:50 ndm: Opkg::Manager: /opt/etc/ndm/netfilter.d/100-vpn-mark: exit code 2. [I] Jan 25 21:34:50 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 25 21:34:50 ndhcpc: IKE0: NDM DHCP Client, v3.2.53. [I] Jan 25 21:34:50 ndhcpc: IKE0: created PID file "/var/run/ndhcpc-nikecli0.pid". [I] Jan 25 21:34:51 l2tp[25202]: Plugin pppol2tp.so loaded. [I] Jan 25 21:34:51 l2tp[25202]: pppd 2.4.4-4 started by root, uid 0 [I] Jan 25 21:34:51 ndm: Network::Interface::EndpointTracker: "L2TP0": added a host route to 80.241.35.38 via 10.27.8.1 (GigabitEthernet1). [E] Jan 25 21:34:51 coalagent: [SecLayer_OnSend] Coala_Send: Network unreachable. [I] Jan 25 21:34:51 pppd_L2TP0: l2tp_control v2.02 [I] Jan 25 21:34:51 pppd_L2TP0: remote host: 80.241.35.38:1701 [I] Jan 25 21:34:51 pppd_L2TP0: local bind: 10.27.8.234:1701 [I] Jan 25 21:34:51 КВАС: Создаем таблицу маршрутизации ID#1001 для 'IKE0'. [E] Jan 25 21:34:52 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/100-unblock-vpn: exit code 1. [I] Jan 25 21:34:52 pppd_L2TP0: creating in-kernel L2TP tunnel (R/L 4273/52456) [I] Jan 25 21:34:52 pppd_L2TP0: creating in-kernel L2TP session (R/L 22912/8656) [I] Jan 25 21:34:52 pppd_L2TP0: L2TP tunnel/session created [I] Jan 25 21:34:52 pppd_L2TP0: PPP channel connected [I] Jan 25 21:34:52 pppd_L2TP0: Using interface ppp0 [I] Jan 25 21:34:52 pppd_L2TP0: Connect: ppp0 <--> l2tp[0] [I] Jan 25 21:34:52 pppd_L2TP0: PAP authentication succeeded [I] Jan 25 21:34:52 pppd_L2TP0: local IP address 10.196.95.202 [I] Jan 25 21:34:52 pppd_L2TP0: remote IP address 80.241.35.38 [I] Jan 25 21:34:52 pppd_L2TP0: primary DNS address 5.34.34.5 [I] Jan 25 21:34:52 pppd_L2TP0: secondary DNS address 37.99.99.37 [I] Jan 25 21:34:52 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 25 21:34:52 ndm: Network::Interface::Base: "L2TP0": interface is up. [I] Jan 25 21:34:52 ndm: Network::Interface::Ip: "L2TP0": interface "L2TP0" is global, priority 53268. [I] Jan 25 21:34:52 ndm: Network::Interface::Ip: "L2TP0": adding default route via L2TP0. [I] Jan 25 21:34:52 ndm: Dns::InterfaceSpecific: adding name server 5.34.34.5. [I] Jan 25 21:34:52 ndm: Dns::InterfaceSpecific: "L2TP0": name server 5.34.34.5 added, domain (default). [I] Jan 25 21:34:52 ndm: Dns::InterfaceSpecific: adding name server 37.99.99.37. [I] Jan 25 21:34:52 ndm: Dns::InterfaceSpecific: "L2TP0": name server 37.99.99.37 added, domain (default). [I] Jan 25 21:34:52 ndm: Network::Interface::Ip: "L2TP0": IP address is 10.196.95.202/32. [I] Jan 25 21:34:52 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "connecting" to "running". [I] Jan 25 21:34:52 ndm: Dns::Manager: name server 5.34.34.5 added, domain (default). [I] Jan 25 21:34:52 ndm: Dns::Manager: name server 37.99.99.37 added, domain (default). [I] Jan 25 21:34:53 ndm: Http::Nginx: loaded SSL certificate for "bccd74bf91143d950a5beea9.keenetic.io". [I] Jan 25 21:34:53 ndm: Http::Nginx: loaded SSL certificate for "amaltea.keenetic.pro". [I] Jan 25 21:34:53 КВАС: Маркируем VPN подключения, когда программное и аппаратное ускорение ПОДКЛЮЧЕНО [I] Jan 25 21:34:53 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:53 ndm: Core::Session: client disconnected. [I] Jan 25 21:34:53 ndm: Http::Manager: updated configuration. [I] Jan 25 21:34:54 ndm: Core::Server: started Session /var/run/ndm.core.socket. [I] Jan 25 21:34:54 ndm: Core::Session: client disconnected. [E] Jan 25 21:34:54 ndm: Opkg::Manager: /opt/etc/ndm/netfilter.d/100-vpn-mark: exit code 2. [E] Jan 25 21:34:54 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 25 21:34:55 КВАС: Производим удаление правил match-set в таблице mangle, цепочке PREROUTING для VPNREDIR [I] Jan 25 21:34:55 КВАС: Производим удаление правил match-set в таблице mangle, цепочке OUTPUT для VPNREDIR [I] Jan 25 21:34:55 КВАС: Создаем таблицу маршрутизации ID#1001 для 'IKE0'. [E] Jan 25 21:34:55 ndm: Opkg::Manager: /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset: exit code 1. [I] Jan 25 21:34:55 КВАС: ¿роверка: Соединение L2TP0::ppp0 успешно подключено. ```
qzeleza commented 8 months ago

Да, нет, все в норме. Ошибки исполнения функции не вижу, зато вижу: что правила сбросились:

[I] Jan 25 21:34:55 КВАС: Производим удаление правил match-set в таблице mangle, цепочке PREROUTING для VPNREDIR [I] Jan 25 21:34:55 КВАС: Производим удаление правил match-set в таблице mangle, цепочке OUTPUT для VPNREDIR [I] Jan 25 21:34:55 КВАС: Создаем таблицу маршрутизации ID#1001 для 'IKE0'.

Если нет результата, значит проблема в другом.

badigit commented 8 months ago

Если нет результата, значит проблема в другом.

  1. Разве проблема не в том что IKEv2 поднимается на 2 минуты позже основного L2TP, и вот после поднятия IKEv2 возможно нужно делать переустановку ipset? Может быть должна сработать какая то логика которая проверит что VPN для обхода поднялся, и только после этого переустанавливать iptables? Вот полный лог ситуации log (4).txt

  2. Также заметил, что в новой версии при выполнении vpn reset теперь дополнительно перезапускается adguard, и теперь это все значительно дольше выполняется, чем раньше. Не понятен смысл, потому последние месяцы обход восстанавливался только переустановкой iptables, без перезапуска adh. Просто теперь это занимает больше времени, без видимой пользы. Было бы хорошо иметь опцию не перезапускать adh, а только переустанавливать iptables.

qzeleza commented 8 months ago

Может быть должна сработать какая то логика которая проверит что VPN для обхода поднялся, и только после этого переустанавливать iptables?

Попробуйте код ниже для файла /opt/etc/ndm/iflayerchanged.d/kvas-ips-reset

#   Подключаем библиотеку с функциями обработки ndm
. /opt/apps/kvas/bin/libs/ndm_d
. /opt/apps/kvas/bin/libs/ndm

tmp_file=/opt/tmp/sub_connection

if [ "${1}" = "hook" ] && [[ ${id} =~ 'PPTP|L2TP' ]]; then
    # В случае отключения PPTP|L2TP соединения через основной интерфейс
    # проще говоря, в случае если подключение к интернету осуществляется
    # через PPTP|L2TP соединение и оно прервалось   - ставим флаг в виде создания файла
    is_cli_iface_global "${id}" && [ "${layer}-${level}" = "ctrl-disabled" ] && touch "${tmp_file}"

    # Отслеживаем, когда подключается к провайдеру через соединения типа PPTP или L2TP
    [ -f "${tmp_file}" ] && [ "${layer}-${level}" = "ctrl-running" ] && is_cli_iface_global "${id}" && {
        # После отключения PPTP|L2TP (которое используется для подключения к провайдеру)
        # и при наличии файла tmp_file - переустанавливаем ipset правила для восстановления
        cmd_vpn_iptable_reset
        logger -t "КВАС"  "Соединение ${id} успешно подключено."
        rm -f "${tmp_file}"
    }
fi
qzeleza commented 8 months ago

Также заметил, что в новой версии при выполнении vpn reset теперь дополнительно перезапускается adguard...

Да, это так и есть, только перегрузка занимает пару секунд не больше. Или Вы говорите о чем-то ином?

badigit commented 8 months ago

Спасибо, протестирую!

Да, это так и есть, только перегрузка занимает пару секунд не больше. Или Вы говорите о чем-то ином?

Ну так то да, у меня это длится секунды три-четыре, но приходится ждать) Не понятно зачем только, если без перезапуска было все ок.

badigit commented 8 months ago

В r4 решение не сработало.. обход блокировок сам не возобновляется. Прикладываю iflayerchanged.log iflayerchanged.log

badigit commented 8 months ago

Судя по коду https://github.com/qzeleza/kvas/blob/847eb5bcfd79e908d11e0d397bae9ec9d19c33fe/opt/etc/ndm/iflayerchanged.d/kvas-ips-reset#L27 идет проверка

case "${layer}-${level}" in
            "ctrl-disabled" )

но судя по моим логам, такого не бывает при ежедневном разрыве провайдером.. бывает layer ipv4 - level disabled layer ctrl - level connecting

так что видимо надо проверять ctrl - connecting.

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

qzeleza commented 8 months ago

layer ipv4 - level disabled layer ctrl - level connecting

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

В следующем релизе подправлю сработку флага ipv4 disabled

qzeleza commented 8 months ago

Подправил, как и писал выше. Прошу дать обратную связь.

qzeleza commented 8 months ago

Тикет закрываем?

wildrun0 commented 8 months ago

Начиная с версии 3 или 4 крайнего релиза, я перестал наблюдать проблемы после обрывов соединения. По моей части проблем больше нет - как там у badigit не знаю

badigit commented 8 months ago

На последнюю версию еще не обновлялся, протестирую.

badigit commented 8 months ago

На r7 проверить не смог - появились другие более критичные ошибки. например Таблица ipset - пуста. Откатился на r5. Откат - работает хорошо)

qzeleza commented 7 months ago

Тикет закрываем?

badigit commented 7 months ago

Пока что проблема есть.. Запишу сегодня свежую отладку

badigit commented 7 months ago

Проблема актуальна.. Вот свежий лог - в течении 10 минут когда было переподключение https://gist.github.com/badigit/c670f3c02e6c6f3e4b1425290e86cfa1#file-log-L133

Ключевые точки в хронологии.

[I] Feb 23 00:02:44 ipsec: 05[IKE] retransmit 4 of request with message ID 148 это момент когда реально отвалился интернет (на домашнем пк скрипт заметил что обход не работает)

[I] Feb 23 00:02:46 dropbear[4528]: Child connection from 10.9.8.92:64068 с домашнего пк пробуем сделать iptables_reset (не успешно и явно раньше времени сработал скрипт)

[I] Feb 23 00:03:34 pppd_L2TP0: No response to 3 echo-requests pppd_L2TP0 заметил что интернет отвалился

[I] Feb 23 00:03:35 ndm: Network::Interface::Base: "L2TP0": "ppp" changed "link" layer state "running" to "connecting". сработал iflayerchanged.d

...потом в течении минуты бурная деятельность кинетика по восстановлению подключений.. .. [I] Feb 23 00:04:53 TESTS: Проверка: iflayerchanged L2TP0 (ppp0) layer ctrl has level running восстановление L2TP

[I] Feb 23 00:05:37 TESTS: Проверка: iflayerchanged IKE0 (nikecli0) layer link has level running восстановление IKE VPN

Наверное надо разбить вопросы на части..

  1. Периодические ошибки вида
    
    [E] Feb 23 00:05:44 КВАС: ОШИБКА::\033[1;31m[ip4_firewall_vpn_mark] Во время маркировки трафика для VPN соединений возникли ошибки.\033[m
    [E] Feb 23 00:05:44 КВАС: ОШИБКА::\033[1;31m[ip4_firewall_exclude_locals] Возникла ошибка при установке правил iptables\033[m
    [E] Feb 23 00:05:35 КВАС: ОШИБКА::\033[1;31mНе удалось определить IP шлюза для соединения nikecli0\033[m


2.  Сам кинетик довольно часто дергает iflayerchanged и вносит неразбериху.

3.  Между пропажей интернета и восстановлением l2TP + IKE прошло примерно 3 минуты..

4. Однозначно понятно что в качестве решения нужно сделать iptables_reset  после того как восстановится основное соединение и VPN IKE0 
Не раньше точно. Попробую поэкспериментировать в этом направлении.

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

Например не очень понятна причина ошибок которые выдает квас в п.1.
qzeleza commented 5 months ago

изменения внесены в 1.1.8 r1 прошу дать обратную связь.

wildrun0 commented 5 months ago

Я так полагаю обратной связи не будет. т.к. тему открывал я, закрываю, у меня проблем больше не наблюдается