Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    DNS Resolver problem (2.7)

    Scheduled Pinned Locked Moved Russian
    38 Posts 5 Posters 1.8k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • K
      Konstanti @rotor
      last edited by

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

      1 Reply Last reply Reply Quote 0
      • R
        rotor
        last edited by

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

        K 1 Reply Last reply Reply Quote 0
        • K
          Konstanti @rotor
          last edited by

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

          1 Reply Last reply Reply Quote 0
          • R
            rotor
            last edited by

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

            K 1 Reply Last reply Reply Quote 0
            • K
              Konstanti @rotor
              last edited by

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

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

              1 Reply Last reply Reply Quote 0
              • T
                tty1
                last edited by

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

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

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

                1 Reply Last reply Reply Quote 0
                • T
                  tty1
                  last edited by

                  Сегодня опять народ жаловался на недоступность сайтов (в частности "под раздачу" попал домен 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).

                  Очень прошу помочь с диагностикой, это реально проблема! :( Может в консоли какие то логи можно посмотреть поглубже?

                  1 Reply Last reply Reply Quote 0
                  • R
                    rotor
                    last edited by

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

                    T 1 Reply Last reply Reply Quote 0
                    • T
                      tty1 @rotor
                      last edited by

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

                      1 Reply Last reply Reply Quote 0
                      • R
                        rotor
                        last edited by

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

                        K 1 Reply Last reply Reply Quote 0
                        • K
                          Konstanti @rotor
                          last edited by

                          @rotor

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

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

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

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

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

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

                          1 Reply Last reply Reply Quote 0
                          • T
                            tty1
                            last edited by tty1

                            Наконец-то сегодня удалось захватить пакеты в момент проблемы!
                            Как раз приехал, говорят не открывается vk.com (на самом деле много чего, просто по нему заметили).
                            Судорожно ломанулся в консоль (лишь бы успеть, знаю, что проблема сама по себе проходит через время!), собрал трафик с LAN и с WAN интерфейсов.
                            Насколько я понимаю, сначала запрос адресуется локальному резолверу, который возвращает Server Failure (response развернул на скрине), затем судя по всему пытается запросить от корня у IANA, но почему то с добавлением суффикса home.arpa и соответственно возвращает No such name vk.com.home.arpa
                            lan_vk_not_resolved.png

                            На WAN порту во время первого запроса само собой ничего нет, далее следуют запросы во внешку (к iana.org) с просьбой подсказать адрес vk.com.home.arpa и соответственно получает ответ, что не знаю такого имени.
                            home_arpa.png

                            Ради эксперимента выключил 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).

                            1 Reply Last reply Reply Quote 0
                            • T
                              tty1
                              last edited by

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

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

                              K 1 Reply Last reply Reply Quote 0
                              • K
                                Konstanti @tty1
                                last edited by

                                @tty1

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

                                T 1 Reply Last reply Reply Quote 0
                                • T
                                  tty1 @Konstanti
                                  last edited by tty1

                                  @Konstanti said in DNS Resolver problem (2.7):

                                  @tty1

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

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

                                  K 1 Reply Last reply Reply Quote 0
                                  • K
                                    Konstanti @tty1
                                    last edited by

                                    @tty1

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

                                    T 1 Reply Last reply Reply Quote 0
                                    • T
                                      tty1 @Konstanti
                                      last edited by tty1

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

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

                                      1 Reply Last reply Reply Quote 0
                                      • T
                                        tty1
                                        last edited by

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

                                        Снова добавляет суффикс 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 в это же время (информации там конечно очень много и к сожалению во многом малопонятной для меня).
                                        Дополню обязательно!

                                        K 1 Reply Last reply Reply Quote 0
                                        • K
                                          Konstanti @tty1
                                          last edited by

                                          @tty1

                                          Насколько я вижу выше , добавляет суффикс добавляет сам хост
                                          120.21
                                          как только получает ответ server failure
                                          возможно , что home.arpa - это ваша внутренняя зона

                                          T 1 Reply Last reply Reply Quote 0
                                          • T
                                            tty1 @Konstanti
                                            last edited by tty1

                                            @Konstanti, совершенно верно, это дефолтная локальная зона.
                                            То есть это уже следствие failure, понял.

                                            Разобрал трафик с логами, очень интересно. В общем когда hihonor.com не резолвился из внутренней сети, я во внешнем трафике не обнаружил ничего совершенно! Ни одного запроса по данному хосту. Но в логах unbound вот такая песня (пришлось грузить на pastebin, форум не пропускает):
                                            https://pastebin.com/raw/CHmL72sT

                                            Затем в 14:22 хост стал пинговаться из сети, в логах unbound следующее:
                                            https://pastebin.com/raw/NGYTLTgZ

                                            Помогите интерпретировать? Опыта не хватает :(
                                            Что вижу своим дилетантским взглядом, в первом случае запросы (sending to target: <com.>) отправлялись на IPv6 адрес, во втором, когда адрес успешно возвращался - IPv4. Тут может быть какая-то связь?
                                            Есть еще один домен (контрольный), по которому есть точное время, когда он не резолвился и когда он же начал находиться. Чуть позже аналогично проанализирую логи по нему.

                                            K 1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post
                                            Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.