DNS Resolver problem (2.7)

Konstanti · Nov 16, 2023, 10:04 AM

@rotor
я немного про другие журналы писал ( не про журнал файрвола на входящие соединения для WAN интерфейса)
Вам нужны системные журналы событий , нет ли там ошибок
Ведется ли журнал Unbound - нет ли там ошибок
показывает ли tcpdump , что запросы udp на 53 порту приходят и уходят нормально в момент проблемы. .....

rotor · Nov 16, 2023, 10:17 AM

журнал 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 пока разбираюсь...

Konstanti · Nov 16, 2023, 10:25 AM

@rotor
Ошибок нет в журнале ,unbound когда проблемы начинаются ?
В системном журнале pf нет ошибок , когда проблемы начинаются ?

rotor · Nov 16, 2023, 10:29 AM

Если взять точку отсчета перезагрузки всей системы, то проблема проявляется через 5-10 минут после старта.

Konstanti · Nov 16, 2023, 10:36 AM

@rotor
Это , к сожалению, ни о чем не говорит . Понимать бы , есть ли ошибки в этот момент

rotor · Nov 16, 2023, 10:38 AM

в этом и вопрос, куда смотреть, что б понять (

Konstanti · Nov 16, 2023, 10:47 AM

@rotor
Для начала
1 смотрите системный журнал PF
2 смотрите журнал unbound на наличие ошибок
3 у unbound в составе пакета есть утилиты , которые позволяют видеть содержимое кэша и не только ( не знаю , есть ли они в составе of , надо проверять )
4 используя tcpdump на wan или lan интерфейсе , можно увидеть , что происходит с dns запросами и ответами

Все это надо делать в момент возникновения проблемы

tty1 · Nov 16, 2023, 3:59 PM

Проблема плавающая, трудно расследовать :( сегодня вот за целый день никто не жаловался, а вчера днем добрая половина сайтов не открывалась.
Журнал unbound смотрел, вроде ничего критичного не видел (но смотрел бегло, пролистывал, мог что то пропустить запросто). Будут проблемы снова - посмотрю.

Товарищ по несчастью, DNSBL используешь? Я что то на него грешу почему то... Его отключаешь - тут же начинает работать. Включаешь обратно - работает (до поры до времени). Хотя возможно просто при его включении/выключении служба рестартится банально.

Очень напрягает данный глюк если честно!

tty1 · Nov 23, 2023, 4:12 PM

Сегодня опять народ жаловался на недоступность сайтов (в частности "под раздачу" попал домен 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 · Nov 24, 2023, 4:08 AM

еще добавлю, сайты перестают открываться (пинг остается и хороший) не одни и те же, а такое ощущение те которые больше пользуются...
у нас один провайдер (Ростелеком), но два канала, один оптика и второй сотовый. основной оптика с проблемой, переключаю на сотовый проблема уходит, можно сделать вывод с железо рабочее ), а вот с провайдеров не понятно, по ка разбираемся...

tty1 · Nov 24, 2023, 6:46 AM

@rotor, у вас пинг остаётся хорошим на клиентских машинах?
В таком случае у вас проблема не с резолвером, клиенты же получают IP адрес хоста.
Или вы про пинг с pfSense (в разделе Diagnostic)?

rotor · Nov 24, 2023, 7:01 AM

пинги хороший и у пользователей и на пфсенсе...
а думаю на DNS Resolver потому, что рестарт помогает не некоторое время...
но уже написал что косяк в каком то виде приходит от провайдера, но вот в каком виде не понятно...

Konstanti · Nov 24, 2023, 7:09 AM

@rotor

Здравствуйте

Скажу еще раз , как можно попытаться обнаружить проблему

1 системные журналы PF на предмет ошибок
2 tcpdump в момент проблемы
a. есть ли запрос/ответ на lan интерфейсе от DNS сервера (udp 53 порт)
б. если ответ есть , смотреть что происходит , когда клиент пытается установить соединение с нужным хостом (lan,wan интерфейсы , tcp )
смотреть лучше ,по-моему, из консоли PF (нагляднее и оперативнее)

Судя по кусочку лога Unbound видно

что по какой-то причине он был остановлен , а потом заново запущен
каких-то ошибок ( отброшенных запросов ) нет

Больше из того что ВЫ предоставляете сказать не могу

tty1 · Nov 30, 2023, 11:31 AM

Наконец-то сегодня удалось захватить пакеты в момент проблемы!
Как раз приехал, говорят не открывается 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).

tty1 · Dec 1, 2023, 6:12 AM

Вот еще вчера нашел интересный кусочек трафика.
google.com не резолвится, однако прямо в то же самое время резолвер отдаёт адрес adblockplus.org

То есть резолвер в этот момент работает! Почему то не возвращает адреса определенных доменов (в подавляющем большинстве случаев это зона .COM).
Хотел повысить уровень логирования до Level 3 (Query level information) - утонул в потоке данных :(
Очень прошу помочь в диагностике. Куда смотреть, что собирать?
Очень актуально! :(

Konstanti · Dec 1, 2023, 6:33 AM

@tty1

а с вышестоящим DNS сервером как происходит общение ?
без DNSSEC ? или ... ?

tty1 · Dec 1, 2023, 6:52 AM

@Konstanti said in DNS Resolver problem (2.7):

@tty1

а с вышестоящим DNS сервером как происходит общение ?
без DNSSEC ? или ... ?

Вообще когда начались проблемы, я по советам с форума выключил DNSSEC, но проблема осталась. Вчера снова включил (раз нет разницы).
Вышестоящими серверами у меня указаны 8.8.8.8 и 1.1.1.1 (изначально стояли провайдерские, я из заменил быстро - грешил на них потому что).

Konstanti · Dec 1, 2023, 7:05 AM

@tty1

Мое мнение . надо смотреть и изучать трафик с вышестоящим сервером
Почему появляется ошибка 2

tty1 · Dec 1, 2023, 7:28 AM

@Konstanti собираю пакеты с фильтром udp/tcp 53 на WAN.
Так же увеличил размер логов и включил расширенное логирование в DNS Resolver (Query level information).

UPD: во вчерашнем дампе трафика с WAN вообще не вижу обращений ни к 8.8.8.8 ни к 1.1.1.1.

tty1 · Dec 1, 2023, 11:42 AM

Мельком решил посмотреть что там насобиралось в WAN трафике, увидел в самых свежих пакетах снова такое:

Снова добавляет суффикс home.arpa! Причем выше всё нормально, запрашивает google.com и прочие домены без него... Что за фантастика, почему он так делает??? :)
Так как пакеты свежие, решил проверить, доступен ли сейчас этот домен (hihonor.com).
Залез на одну из машин, запустил пинг:

ping hihonor.com
ping: hihonor.com: Временный сбой в разрешении имен

запустил с домашнего:

ping hihonor.com
PING hihonor.com (43.134.158.9) 56(84) bytes of data.
64 bytes from 43.134.158.9 (43.134.158.9): icmp_seq=2 ttl=40 time=279 ms

Самое главное, что теперь у меня есть точное время, когда возникла проблема с резолвом! Вечером буду смотреть трафик (ожидаю в это время там увидеть DNS Query hihonor.com.home.arpa) и смотреть расширенные логи unbound в это же время (информации там конечно очень много и к сожалению во многом малопонятной для меня).
Дополню обязательно!