DNS Resolver unbound stoppt und startet sich immer wieder neu

[ciscler]

Hallo zusammen,

ich hoffe ich bin hier richtig. Ich habe eine PFSense am laufen und habe das Problem, das der DNS Resolver Dienst ständig stoppt und dann wieder neu startet. Habe mir auch schon den Watchdog installiert, um den Service zu überwachen. Dieser Meldet auch ständig, das der Dienst ubound gestoppt wurde.
Hat Jemand eine Idee voran es liegen könnte?

Hier mal die Logs, von dem Ubound:

May 24 11:03:38 unbound 67241:0 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
May 24 11:03:38 unbound 67241:0 info: average recursion processing time 0.134977 sec
May 24 11:03:38 unbound 67241:0 info: histogram of recursion processing times
May 24 11:03:38 unbound 67241:0 info: [25%]=0 median[50%]=0 [75%]=0
May 24 11:03:38 unbound 67241:0 info: lower(secs) upper(secs) recursions
May 24 11:03:38 unbound 67241:0 info: 0.131072 0.262144 1
May 24 11:03:38 unbound 67241:0 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 24 11:03:38 unbound 67241:0 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
May 24 11:03:38 unbound 67241:0 info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 24 11:03:38 unbound 67241:0 info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
May 24 11:03:38 unbound 67241:0 info: average recursion processing time 0.037301 sec
May 24 11:03:38 unbound 67241:0 info: histogram of recursion processing times
May 24 11:03:38 unbound 67241:0 info: [25%]=0 median[50%]=0 [75%]=0
May 24 11:03:38 unbound 67241:0 info: lower(secs) upper(secs) recursions
May 24 11:03:38 unbound 67241:0 info: 0.032768 0.065536 1
May 24 11:03:38 unbound 67241:0 info: server stats for thread 3: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 24 11:03:38 unbound 67241:0 info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
May 24 11:03:38 unbound 67241:0 info: average recursion processing time 0.063625 sec

Beste Grüße

[ciscler]

May 24 11:17:19 unbound 99946:0 info: start of service (unbound 1.9.6).
May 24 11:17:20 unbound 99946:2 info: generate keytag query _ta-4f66. NULL IN
May 24 11:17:22 unbound 99946:0 info: service stopped (unbound 1.9.6).
May 24 11:17:22 unbound 99946:0 info: server stats for thread 0: 15 queries, 0 answers from cache, 15 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 24 11:17:22 unbound 99946:0 info: server stats for thread 0: requestlist max 7 avg 1.33333 exceeded 0 jostled 0
May 24 11:17:22 unbound 99946:0 info: average recursion processing time 0.054047 sec
May 24 11:17:22 unbound 99946:0 info: histogram of recursion processing times
May 24 11:17:22 unbound 99946:0 info: [25%]=0.034816 median[50%]=0.049152 [75%]=0.063488
May 24 11:17:22 unbound 99946:0 info: lower(secs) upper(secs) recursions
May 24 11:17:22 unbound 99946:0 info: 0.008192 0.016384 1
May 24 11:17:22 unbound 99946:0 info: 0.016384 0.032768 2
May 24 11:17:22 unbound 99946:0 info: 0.032768 0.065536 8
May 24 11:17:22 unbound 99946:0 info: 0.065536 0.131072 2
May 24 11:17:22 unbound 99946:0 info: 0.131072 0.262144 1
May 24 11:17:22 unbound 99946:0 info: server stats for thread 1: 12 queries, 0 answers from cache, 12 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 24 11:17:22 unbound 99946:0 info: server stats for thread 1: requestlist max 32 avg 4.58333 exceeded 0 jostled 0
May 24 11:17:22 unbound 99946:0 info: average recursion processing time 0.114685 sec
May 24 11:17:22 unbound 99946:0 info: histogram of recursion processing times
May 24 11:17:22 unbound 99946:0 info: [25%]=0.0786432 median[50%]=0.117965 [75%]=0.196608
May 24 11:17:22 unbound 99946:0 info: lower(secs) upper(secs) recursions
May 24 11:17:22 unbound 99946:0 info: 0.032768 0.065536 2

[ciscler]

Hat Jemand eine Idee was es sein könnte?

[viragomann]

Hallo,

in diesen Log Auszügen kann ich keine Gründe für das Problem finden. Gibt es im System- oder im DHCP-Log Hinweise?

Du kannst auch mal versuchen "DHCP Registration" in der Resolver Konfig zu deaktivieren.

[ciscler]

Danke für deine Antwort.
"DHCP Registration" hab ich mal deaktiviert hat aber keinen Effekt.

Hier mal die System-Logs:

May 24 16:50:11 rc.gateway_alarm 10345 >>> Gateway alarm: WAN_DHCP6 (Addr:2001:4860:4860::8888 Alarm:1 RTT:11.100ms RTTsd:.293ms Loss:33%)
May 24 16:50:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:49:18 sshd 7863 Connection closed by 192.168.0.102 port 34744 [preauth]
May 24 16:49:16 rc.gateway_alarm 96215 >>> Gateway alarm: WAN_DHCP6 (Addr:2001:4860:4860::8888 Alarm:1 RTT:10.866ms RTTsd:.381ms Loss:33%)
May 24 16:49:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:48:03 dhcpleases /etc/hosts changed size from original!
May 24 16:47:58 dhcpleases kqueue error: unknown
May 24 16:47:57 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
May 24 16:47:57 dhcpleases /etc/hosts changed size from original!
May 24 16:47:52 dhcpleases kqueue error: unknown
May 24 16:47:52 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
May 24 16:47:52 dhcpleases /etc/hosts changed size from original!
May 24 16:47:47 dhcpleases kqueue error: unknown
May 24 16:47:47 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
May 24 16:47:47 dhcpleases /etc/hosts changed size from original!
May 24 16:47:42 dhcpleases kqueue error: unknown

[Bob.Dig]

@ciscler welche Version von pfSense?

[ciscler]

Ich benutze die aktuellste Version:

2.4.5-RELEASE (amd64)
built on Tue Mar 24 15:25:50 EDT 2020
FreeBSD 11.3-STABLE

Hier hab ich noch etwas in den System logs gefunden:

May 24 16:58:01 php-cgi servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1590332281] unbound[39380:0] error: bind: address already in use [1590332281] unbound[39380:0] fatal error: could not open ports'
May 24 16:58:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:57:01 php-cgi servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1590332221] unbound[1762:0] error: bind: address already in use [1590332221] unbound[1762:0] fatal error: could not open ports'
May 24 16:57:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:54:18 sshd 25320 Connection reset by 192.168.0.102 port 34774 [preauth]
May 24 16:54:01 php-cgi servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1590332041] unbound[59911:0] error: bind: address already in use [1590332041] unbound[59911:0] fatal error: could not open ports'
May 24 16:54:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:53:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (DNS Resolver)
May 24 16:51:01 php-cgi servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1590331861] unbound[31709:0] error: bind: address already in use [1590331861] unbound[31709:0] fatal error: could not open ports'

[JeGr]

Ich würde als erstes einmal damit beginnen den Watchdog wieder auszumachen und rauszuschmeißen und anschließend das Loglevel von Unbound/DNS Resolver etwas zu erhöhen, wenn er sich selbst beendet. Angeblich läuft er ja nicht und "muss neugestartet" werden. Das bezweifle ich eher. Der Normalfall ist nicht, dass ein Dienst per Watchdog im Minutenrhythmus neu getreten werden muss. Wenn das der Fall ist, sollte man das Problem suchen, nicht mit einem Watchdog das Problem erschlagen ;)

Ansonsten ist DHCP im DNS komplett aus? Oder teilweise? Mal ein wenig mehr Details zur Konfiguration wären hilfreich, sonst ist das hier nur Glaskugellesen. :)

[ciscler]

Hi,

habe den Watchdog entfernt. Hier mal meine Konfiuration von dem DNS Resolver zudem habe ich das log level auf Level 2 gestellt.

Und hier die Logs vom unbound:

Was kann ich euch noch liefern?

[ciscler]

Der Status vom DNS Resolver sieht wie folgt auf. Habe jetzt mehrmals auf Status -> DNS Resolver gelickt:

[ciscler]

[ciscler]

Hat irgendwer noch eine Idee?

[fireodo]

@ciscler said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

Hat irgendwer noch eine Idee?

Könnte dir das da Unbound update vielleicht helfen?

[ciscler]

@fireodo und wie soll ich unbound updaten?

[fireodo]

@ciscler said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

@fireodo und wie soll ich unbound updaten?

Folge dem Link auf Redmine und lies dir durch was dort steht, oder öffne eine SSH Verbindung zu deiner pfsense und gib dort an der Kommandozeile: pkg upgrade -y unbound
ein.

[ciscler]

@fireodo said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

pkg upgrade -y unbound

Habe das update durchgeführt, hat aber keinen positiven Effekt. Stopped immer noch.

[fireodo]

@ciscler said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

@fireodo said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

pkg upgrade -y unbound

Habe das update durchgeführt, hat aber keinen positiven Effekt. Stopped immer noch.

Was hast du für einen Internet Zugang? In einem Deiner Logfiles ist ein Gateway Alarm - wenn das Gateway ständig up und down ist dann startet der unbound auch immer wieder ... eine Vermutung meinerseits ...

[fireodo]

@JeGr said in DNS Resolver unbound stoppt und startet sich immer wieder neu:

Mal ein wenig mehr Details zur Konfiguration wären hilfreich, sonst ist das hier nur Glaskugellesen. :)

Da schließ ich mich an ...

[ciscler]

Guter Punkt mit dem Gateway Alarm. Die pfsense hängt an einem VDSL Anschluss.
Die Gateways sind up und flappen auch nicht. Ich habe den IPV6 auf unmonitored gesetzt.

Dennoch habe ich in den logs jede menge Gateway errors:

Ich habe keine Ahnung warum das so ist. Die Internetverbindung läuft stabil. Dauerping auf 1.1.1.1 oder google laufen ohne Probleme.

Auch wenn ich die Gatway events disable startet der unbound immer wieder durch..

Vielleicht sollte ich die pfsense platt machen und neu installieren.

Hier scheint einiges im Argen zu sein.

[JeGr]

Nur dein DHCP6 Gateway ist auf unmonitored. Der v4 nicht. Könnte also durchaus sein, dass der daran Schuld ist. Du könntest bei beiden mal unmonitored gehen oder zumindest die Gateway Actions disablen. Zudem solltest du im normalen Syslog da auch sehen, dass alle 5-10s was neugeladen wird? Aber ich würde auch sagen, Reset, Neu anfangen und Stückweise rantasten und sichern zwischendurch - vielleicht findet sich so der Schuldige (oder es läuft dann einfach sauber) :)