DNS Resolver problem (2.7)
-
Товарищи, столкнулся с проблемой, не пойму куда копать.
Время от времени спонтанно DNS Resolver перестает возвращать какие-то отдельные адреса, при этом другие - ОК (не из кэша!). Плюс "проблемные" адреса в тот же момент времени спокойно определяются из веб-интерфейса pfSense, пингуются в разделе Diagnostic. А клиентам ответ не приходит!
Чаще всего замечена проблема с зоной .com (не открывались в течение дня reddit.com, habr.com, anydesk.com, netgate.com). Проходит минут 5-10 и адреса снова резолвятся! Что вообще может быть, в какую сторону хотя бы смотреть, что проверить, в какие логи глядеть в момент проблемы?
Большой парк pfSense на 2.6 - никогда такого не было нигде, впервые поставил 2.7 и получил такое поведение.
Поменял DNS Resolver на Forwarder, глюк вроде пропал, но с ним ведь DNSBL не работает, а отключать его бы крайне не хотелось.
Прошу о помощи. -
Доброго времени...
присоединяюсь к автору за помощью!
схожая ситуация, но приход к такой ситуации немного другой: на чалось на 2.6 версии, пропал доступ к нескольким сайтам (mail.ru, youtube.com, раздет картинки на yandex.ru, доступ к почте почтовым клиентом), подобная ситуация была на 2.5 версии - там обновились с 2.5 на 2.6 и всё заработало. и вот снова подобная ситуация, обновились на 2.7, но ситуация не изменилась.
причем не понятно что перехватывает ДНС, поскольку перезагрузка и смена в ручную адреса ДНС помогает на 5-10 минут, всё работает и летает, через 5-10 минут всё возвращается.
у нас в 3х местах стоят, все обновили до 2.7 все, а проблему только у одного...
неделю уже голову ломаем, все настройки на всех 3х одинаковые, а проблему у одного... -
@rotor
ЗдравствуйтеЯ бы , на Вашем месте, начинал бы с проверок журналов системы и unbound . Нет ли там ошибок каких-нибудь . tcpdump тоже в помощь ( udp на 53 порту)
-
udp с 53 портом блокирован фаерволом.
а системный журнал показывает блокировку:Действие Время Интерфейс Источник Назначение Протокол Nov 16 16:37:10 WAN 78.128.113.94:56224 ххх.ххх.ххх.ххх:10643 TCP:S Nov 16 16:37:15 WAN 79.124.59.82:54775 ххх.ххх.ххх.ххх:31593 TCP:S Nov 16 16:37:17 WAN 185.81.68.118:50489 ххх.ххх.ххх.ххх:57036 TCP:S Nov 16 16:37:17 WAN 185.81.68.118:50489 ххх.ххх.ххх.ххх:23731 TCP:S Nov 16 16:37:19 WAN 89.248.165.29:42852 ххх.ххх.ххх.ххх:43482 TCP:S Nov 16 16:37:22 WAN 92.63.197.110:43496 ххх.ххх.ххх.ххх:31305 TCP:S Nov 16 16:37:27 WAN 84.54.51.116:36200 ххх.ххх.ххх.ххх:8080 TCP:S Nov 16 16:37:33 WAN 210.99.134.109:61561 ххх.ххх.ххх.ххх:5173 TCP:RA Nov 16 16:37:34 WAN 79.124.58.166:55186 ххх.ххх.ххх.ххх:52399 TCP:S
в таком виде, тут мне не понятно пока.
-
@rotor
я немного про другие журналы писал ( не про журнал файрвола на входящие соединения для WAN интерфейса)
Вам нужны системные журналы событий , нет ли там ошибок
Ведется ли журнал Unbound - нет ли там ошибок
показывает ли tcpdump , что запросы udp на 53 порту приходят и уходят нормально в момент проблемы. ..... -
журнал Unbound:
Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.000000 0.000001 9 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.008192 0.016384 25 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.016384 0.032768 4 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.032768 0.065536 107 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.065536 0.131072 107 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.131072 0.262144 67 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.262144 0.524288 20 Nov 16 16:29:52 unbound 37807 [37807:0] info: 0.524288 1.000000 2 Nov 16 16:29:52 unbound 37807 [37807:0] info: 1.000000 2.000000 4 Nov 16 16:29:52 unbound 37807 [37807:0] info: 2.000000 4.000000 3 Nov 16 16:29:52 unbound 37807 [37807:0] info: 4.000000 8.000000 2 Nov 16 16:29:52 unbound 37807 [37807:0] info: 8.000000 16.000000 9 Nov 16 16:29:52 unbound 37807 [37807:0] notice: Restart of unbound 1.17.1. Nov 16 16:29:52 unbound 37807 [37807:0] notice: init module 0: validator Nov 16 16:29:52 unbound 37807 [37807:0] notice: init module 1: iterator Nov 16 16:29:52 unbound 37807 [37807:0] info: start of service (unbound 1.17.1). Nov 16 16:29:53 unbound 37807 [37807:0] info: generate keytag query _ta-4f66. NULL IN Nov 16 16:29:53 unbound 37807 [37807:0] info: service stopped (unbound 1.17.1). Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 Nov 16 16:29:53 unbound 37807 [37807:0] info: average recursion processing time 0.188825 sec Nov 16 16:29:53 unbound 37807 [37807:0] info: histogram of recursion processing times Nov 16 16:29:53 unbound 37807 [37807:0] info: [25%]=0 median[50%]=0 [75%]=0 Nov 16 16:29:53 unbound 37807 [37807:0] info: lower(secs) upper(secs) recursions Nov 16 16:29:53 unbound 37807 [37807:0] info: 0.131072 0.262144 1 Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0 Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0 Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 16 16:29:53 unbound 37807 [37807:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0 Nov 16 16:29:56 unbound 86349 [86349:0] notice: init module 0: validator Nov 16 16:29:56 unbound 86349 [86349:0] notice: init module 1: iterator Nov 16 16:29:56 unbound 86349 [86349:0] info: start of service (unbound 1.17.1). Nov 16 16:29:56 unbound 86349 [86349:1] info: generate keytag query _ta-4f66. NULL IN
больше кода не принимает, в спам отправляет меня (((
а tcpdump пока разбираюсь... -
@rotor
Ошибок нет в журнале ,unbound когда проблемы начинаются ?
В системном журнале pf нет ошибок , когда проблемы начинаются ? -
Если взять точку отсчета перезагрузки всей системы, то проблема проявляется через 5-10 минут после старта.
-
@rotor
Это , к сожалению, ни о чем не говорит . Понимать бы , есть ли ошибки в этот момент -
в этом и вопрос, куда смотреть, что б понять (
-
@rotor
Для начала
1 смотрите системный журнал PF
2 смотрите журнал unbound на наличие ошибок
3 у unbound в составе пакета есть утилиты , которые позволяют видеть содержимое кэша и не только ( не знаю , есть ли они в составе of , надо проверять )
4 используя tcpdump на wan или lan интерфейсе , можно увидеть , что происходит с dns запросами и ответамиВсе это надо делать в момент возникновения проблемы
-
Проблема плавающая, трудно расследовать :( сегодня вот за целый день никто не жаловался, а вчера днем добрая половина сайтов не открывалась.
Журнал unbound смотрел, вроде ничего критичного не видел (но смотрел бегло, пролистывал, мог что то пропустить запросто). Будут проблемы снова - посмотрю.Товарищ по несчастью, DNSBL используешь? Я что то на него грешу почему то... Его отключаешь - тут же начинает работать. Включаешь обратно - работает (до поры до времени). Хотя возможно просто при его включении/выключении служба рестартится банально.
Очень напрягает данный глюк если честно!
-
Сегодня опять народ жаловался на недоступность сайтов (в частности "под раздачу" попал домен vk.com).
Симптомы те же - хост не резолвится с клиентов, но пингуется из GUI.
Пока был занят более приоритетной задачей, хост стал доступен (минут 10-15 прошло).
Я так понимаю, что проблема эта имеется постоянно, весь лишь вопрос в том, замечают её пользователи, или нет. :(В логах unbound последние события вообще 0:06 (время на pf правильное), а проблема в районе 12 часов наблюдалась.
Лог прилагаю:Nov 23 00:06:09 unbound 68171 [68171:0] info: service stopped (unbound 1.17.1). Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 0: 1737 queries, 878 answers from cache, 859 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 0: requestlist max 7 avg 0.123399 exceeded 0 jostled 0 Nov 23 00:06:11 unbound 68171 [68171:0] info: average recursion processing time 0.098742 sec Nov 23 00:06:11 unbound 68171 [68171:0] info: histogram of recursion processing times Nov 23 00:06:11 unbound 68171 [68171:0] info: [25%]=0.00551443 median[50%]=0.0306062 [75%]=0.106364 Nov 23 00:06:11 unbound 68171 [68171:0] info: lower(secs) upper(secs) recursions Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000000 0.000001 33 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000256 0.000512 16 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000512 0.001024 28 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.001024 0.002048 49 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.002048 0.004096 42 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.004096 0.008192 135 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.008192 0.016384 64 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.016384 0.032768 72 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.032768 0.065536 128 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.065536 0.131072 124 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.131072 0.262144 100 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.262144 0.524288 41 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.524288 1.000000 18 Nov 23 00:06:11 unbound 68171 [68171:0] info: 1.000000 2.000000 6 Nov 23 00:06:11 unbound 68171 [68171:0] info: 2.000000 4.000000 3 Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 1: 6744 queries, 3621 answers from cache, 3123 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 1: requestlist max 23 avg 0.319885 exceeded 0 jostled 0 Nov 23 00:06:11 unbound 68171 [68171:0] info: average recursion processing time 0.079613 sec Nov 23 00:06:11 unbound 68171 [68171:0] info: histogram of recursion processing times Nov 23 00:06:11 unbound 68171 [68171:0] info: [25%]=0.00422213 median[50%]=0.0194592 [75%]=0.0820902 Nov 23 00:06:11 unbound 68171 [68171:0] info: lower(secs) upper(secs) recursions Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000000 0.000001 141 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000256 0.000512 132 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000512 0.001024 122 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.001024 0.002048 275 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.002048 0.004096 96 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.004096 0.008192 479 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.008192 0.016384 257 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.016384 0.032768 317 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.032768 0.065536 426 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.065536 0.131072 385 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.131072 0.262144 290 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.262144 0.524288 129 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.524288 1.000000 49 Nov 23 00:06:11 unbound 68171 [68171:0] info: 1.000000 2.000000 20 Nov 23 00:06:11 unbound 68171 [68171:0] info: 2.000000 4.000000 4 Nov 23 00:06:11 unbound 68171 [68171:0] info: 4.000000 8.000000 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 2: 2627 queries, 1323 answers from cache, 1304 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 2: requestlist max 17 avg 0.148773 exceeded 0 jostled 0 Nov 23 00:06:11 unbound 68171 [68171:0] info: average recursion processing time 0.103109 sec Nov 23 00:06:11 unbound 68171 [68171:0] info: histogram of recursion processing times Nov 23 00:06:11 unbound 68171 [68171:0] info: [25%]=0.00346839 median[50%]=0.0212427 [75%]=0.0839028 Nov 23 00:06:11 unbound 68171 [68171:0] info: lower(secs) upper(secs) recursions Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000000 0.000001 46 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000128 0.000256 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000256 0.000512 21 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000512 0.001024 79 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.001024 0.002048 136 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.002048 0.004096 62 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.004096 0.008192 176 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.008192 0.016384 88 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.016384 0.032768 145 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.032768 0.065536 180 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.065536 0.131072 157 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.131072 0.262144 119 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.262144 0.524288 54 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.524288 1.000000 26 Nov 23 00:06:11 unbound 68171 [68171:0] info: 1.000000 2.000000 8 Nov 23 00:06:11 unbound 68171 [68171:0] info: 2.000000 4.000000 4 Nov 23 00:06:11 unbound 68171 [68171:0] info: 4.000000 8.000000 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: 8.000000 16.000000 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 3: 11381 queries, 6008 answers from cache, 5373 recursions, 0 prefetch, 0 rejected by ip ratelimiting Nov 23 00:06:11 unbound 68171 [68171:0] info: server stats for thread 3: requestlist max 17 avg 0.531547 exceeded 0 jostled 0 Nov 23 00:06:11 unbound 68171 [68171:0] info: average recursion processing time 0.089854 sec Nov 23 00:06:11 unbound 68171 [68171:0] info: histogram of recursion processing times Nov 23 00:06:11 unbound 68171 [68171:0] info: [25%]=0.00423958 median[50%]=0.0166791 [75%]=0.0749658 Nov 23 00:06:11 unbound 68171 [68171:0] info: lower(secs) upper(secs) recursions Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000000 0.000001 267 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000128 0.000256 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000256 0.000512 175 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.000512 0.001024 166 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.001024 0.002048 555 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.002048 0.004096 147 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.004096 0.008192 920 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.008192 0.016384 445 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.016384 0.032768 583 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.032768 0.065536 686 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.065536 0.131072 589 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.131072 0.262144 501 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.262144 0.524288 191 Nov 23 00:06:11 unbound 68171 [68171:0] info: 0.524288 1.000000 87 Nov 23 00:06:11 unbound 68171 [68171:0] info: 1.000000 2.000000 44 Nov 23 00:06:11 unbound 68171 [68171:0] info: 2.000000 4.000000 11 Nov 23 00:06:11 unbound 68171 [68171:0] info: 4.000000 8.000000 1 Nov 23 00:06:11 unbound 68171 [68171:0] info: 8.000000 16.000000 4 Nov 23 00:06:28 unbound 8641 [8641:0] notice: init module 0: iterator Nov 23 00:06:28 unbound 8641 [8641:0] info: start of service (unbound 1.17.1).
Очень прошу помочь с диагностикой, это реально проблема! :( Может в консоли какие то логи можно посмотреть поглубже?
-
еще добавлю, сайты перестают открываться (пинг остается и хороший) не одни и те же, а такое ощущение те которые больше пользуются...
у нас один провайдер (Ростелеком), но два канала, один оптика и второй сотовый. основной оптика с проблемой, переключаю на сотовый проблема уходит, можно сделать вывод с железо рабочее ), а вот с провайдеров не понятно, по ка разбираемся... -
@rotor, у вас пинг остаётся хорошим на клиентских машинах?
В таком случае у вас проблема не с резолвером, клиенты же получают IP адрес хоста.
Или вы про пинг с pfSense (в разделе Diagnostic)? -
пинги хороший и у пользователей и на пфсенсе...
а думаю на DNS Resolver потому, что рестарт помогает не некоторое время...
но уже написал что косяк в каком то виде приходит от провайдера, но вот в каком виде не понятно... -
Здравствуйте
Скажу еще раз , как можно попытаться обнаружить проблему
1 системные журналы PF на предмет ошибок
2 tcpdump в момент проблемы
a. есть ли запрос/ответ на lan интерфейсе от DNS сервера (udp 53 порт)
б. если ответ есть , смотреть что происходит , когда клиент пытается установить соединение с нужным хостом (lan,wan интерфейсы , tcp )
смотреть лучше ,по-моему, из консоли PF (нагляднее и оперативнее)Судя по кусочку лога Unbound видно
- что по какой-то причине он был остановлен , а потом заново запущен
- каких-то ошибок ( отброшенных запросов ) нет
Больше из того что ВЫ предоставляете сказать не могу
-
Наконец-то сегодня удалось захватить пакеты в момент проблемы!
Как раз приехал, говорят не открывается vk.com (на самом деле много чего, просто по нему заметили).
Судорожно ломанулся в консоль (лишь бы успеть, знаю, что проблема сама по себе проходит через время!), собрал трафик с LAN и с WAN интерфейсов.
Насколько я понимаю, сначала запрос адресуется локальному резолверу, который возвращает Server Failure (response развернул на скрине), затем судя по всему пытается запросить от корня у IANA, но почему то с добавлением суффикса home.arpa и соответственно возвращает No such name vk.com.home.arpa
На WAN порту во время первого запроса само собой ничего нет, далее следуют запросы во внешку (к iana.org) с просьбой подсказать адрес vk.com.home.arpa и соответственно получает ответ, что не знаю такого имени.
Ради эксперимента выключил pfBlockerNG - vk.com сразу же открылся. Я включил блокировщик обратно, ВК продолжает работать (в принципе оно и понятно, вероятнее всего адрес уже берется из локального кэша ПК). Тогда решил еще на всякий случай посмотреть трафик на ПК. Но сайт wireshark.org не открылся (так же не возвращался IP адрес). Отключил pfBlockerNG - загрузил вайршарк без проблем. Опять включил блокировщик - работают ВК и wireshark.org (очевидно, что тут локальный кэш в деле!). Далее wireshark попросил установить npcap ну и вы поняли :) npcap.com не открылся (то есть версия, что возможно включение/отключение pfBlocker приводит к перезапуску резолвера и всё начинает работать провалилась).
Из наблюдений: такое ощущение, что проблема имеет периодичность (чаще всего жалуются в первой половине дня, около 10-11-12 часов - сильно примерно!). Думал может в это время обновляются алиасы и происходит рестарт pfBlocker, в течение которого резолвер не отвечает на запросы. Посмотрел в cron - обновление алиасов происходит в 12:30 (выходит мимо). Да и может ли Reload длиться минут 7-10? Вряд ли же.
В настройках заинтересовала галка Resolver Live Sync (по дефолту она выключена!). Из описания: "Enable When enabled, updates to the DNS Resolver DNSBL database will be performed Live without reloading the Resolver. This will allow for more frequent DNSBL Updates (ie: Hourly) without losing DNS Resolution." - чушутся руки её установить, однако решил уточнить, правильно ли я понимаю её смысл!?PS. ну и да, в логах (системных, unbound) никаких ошибок, предупреждений по прежнему нет.
UPD: посмотрел внимательно cron, обновление алиасов это немного другая задача (update_urltables), обновление pfBlocker происходит каждые 8 часов (но по времени не совпадает - 0, 8, 16).
-
Вот еще вчера нашел интересный кусочек трафика.
google.com не резолвится, однако прямо в то же самое время резолвер отдаёт адрес adblockplus.org
То есть резолвер в этот момент работает! Почему то не возвращает адреса определенных доменов (в подавляющем большинстве случаев это зона .COM).
Хотел повысить уровень логирования до Level 3 (Query level information) - утонул в потоке данных :(
Очень прошу помочь в диагностике. Куда смотреть, что собирать?
Очень актуально! :( -
а с вышестоящим DNS сервером как происходит общение ?
без DNSSEC ? или ... ?