Unbound is restarting every 30 minutes

[mumpitz]

Today I noticed that unbound has been restarting every 30 minutes since the end of September, which was definitely not the case before.
Is this normal now?

19:30:00	unbound: [27958:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
19:29:50	unbound: [27958:0]	info: start of service (unbound 1.18.0).
19:29:50	unbound: [27958:0]	notice: init module 1: iterator
19:29:50	unbound: [27958:0]	notice: init module 0: validator
19:29:49	unbound: [27958:0]	notice: Restart of unbound 1.18.0.
19:29:48	unbound: [27958:0]	info: 0.524288 1.000000 1
19:29:48	unbound: [27958:0]	info: 0.262144 0.524288 13
19:29:48	unbound: [27958:0]	info: 0.131072 0.262144 33
19:29:48	unbound: [27958:0]	info: 0.065536 0.131072 20
19:29:48	unbound: [27958:0]	info: 0.032768 0.065536 5
19:29:48	unbound: [27958:0]	info: 0.016384 0.032768 3
19:29:48	unbound: [27958:0]	info: 0.000000 0.000001 5
19:29:48	unbound: [27958:0]	info: lower(secs) upper(secs) recursions
19:29:48	unbound: [27958:0]	info: [25%]=0.0884736 median[50%]=0.158875 [75%]=0.238313
19:29:48	unbound: [27958:0]	info: histogram of recursion processing times
19:29:48	unbound: [27958:0]	info: average recursion processing time 0.160369 sec
19:29:48	unbound: [27958:0]	info: server stats for thread 0: requestlist max 2 avg 0.117647 exceeded 0 jost led 0
19:29:48	unbound: [27958:0]	info: server stats for thread 0: 146 queries, 66 answers from cache, 80 recursi ons, 5 prefetch, 0 rejected by ip ratelimiting
19:29:48	unbound: [27958:0]	info: service stopped (unbound 1.18.0).
19:03:03	unbound: [27958:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
18:59:49	unbound: [27958:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
18:59:49	unbound: [27958:0]	info: start of service (unbound 1.18.0).
18:59:49	unbound: [27958:0]	notice: init module 1: iterator
18:59:49	unbound: [27958:0]	notice: init module 0: validator
18:59:47	unbound: [27958:0]	notice: Restart of unbound 1.18.0.
18:59:47	unbound: [27958:0]	info: 0.262144 0.524288 4
18:59:47	unbound: [27958:0]	info: 0.131072 0.262144 20
18:59:47	unbound: [27958:0]	info: 0.065536 0.131072 13
18:59:47	unbound: [27958:0]	info: 0.032768 0.065536 3
18:59:47	unbound: [27958:0]	info: 0.016384 0.032768 2
18:59:47	unbound: [27958:0]	info: 0.000000 0.000001 1
18:59:47	unbound: [27958:0]	info: lower(secs) upper(secs) recursions
18:59:47	unbound: [27958:0]	info: [25%]=0.0894818 median[50%]=0.147456 [75%]=0.217907
18:59:47	unbound: [27958:0]	info: histogram of recursion processing times
18:59:47	unbound: [27958:0]	info: average recursion processing time 0.154353 sec
18:59:47	unbound: [27958:0]	info: server stats for thread 0: requestlist max 1 avg 0.037037 exceeded 0 jost led 0
18:59:47	unbound: [27958:0]	info: server stats for thread 0: 104 queries, 61 answers from cache, 43 recursi ons, 11 prefetch, 0 rejected by ip ratelimiting
18:59:47	unbound: [27958:0]	info: service stopped (unbound 1.18.0).

[hvacguy (Shaun HVAC)]

Unbound starts and stops a lot for unknown reason

Hello, Inside Logs => System Logs => (section) DNS: Unbound I am seeing Unbound stopping and starting too many times. For instance, in the past 16.5 hours, it stopped 241 times as per the logs. Please see: What could be the reason for that? Thanks,

[mumpitz]

Ok thanks, so there is no solution yet ?
Does this mean I have any disadvantages that other things don’t work as they should?

[jon]

I see the same messages unbound restart messages in the messages log.

I am curious, are there any issues you see when these unbound restarts happen (beside the restart message)?

[peppetech]

I just noticed that for the past 10 days unbound has been restarting every 30 minutes.

This IPFire has an older version of unbound and I have the new RPZ addon installed, otherwise, I don’t see anything unusual.

IPFire diagnostics
Section: unbound
Date: September 09, 2024

00:12:46 unbound: [32538:0]  info: service stopped (unbound 1.19.0).
00:12:46 unbound: [32538:0]  info: server stats for thread 0: 50 queries, 37 answers from cache, 13 recursions, 0 prefetch, 0 rejected by ip ratelimiting
00:12:46 unbound: [32538:0]  info: server stats for thread 0: requestlist max 1 avg 0.0769231 exceeded 0 jostled 0
00:12:46 unbound: [32538:0]  info: average recursion processing time 2.399750 sec
00:12:46 unbound: [32538:0]  info: histogram of recursion processing times
00:12:46 unbound: [32538:0]  info: [25%]=1.0625 median[50%]=1.875 [75%]=3.1
00:12:46 unbound: [32538:0]  info: lower(secs) upper(secs) recursions
00:12:46 unbound: [32538:0]  info:    0.524288    1.000000 3
00:12:46 unbound: [32538:0]  info:    1.000000    2.000000 4
00:12:46 unbound: [32538:0]  info:    2.000000    4.000000 5
00:12:46 unbound: [32538:0]  info:    8.000000   16.000000 1
00:12:46 unbound: [32538:0]  notice: Restart of unbound 1.19.0.
00:12:46 unbound: [32538:0]  notice: init module 0: respip
00:12:46 unbound: [32538:0]  notice: init module 1: validator
00:12:46 unbound: [32538:0]  notice: init module 2: iterator
00:12:53 unbound: [32538:0]  info: start of service (unbound 1.19.0).
00:17:53 unbound: [32538:0]  info: generate keytag query _ta-4a5c-4f66. NULL IN
00:42:47 unbound: [32538:0]  info: service stopped (unbound 1.19.0).
00:42:47 unbound: [32538:0]  info: server stats for thread 0: 22 queries, 3 answers from cache, 19 recursions, 0 prefetch, 0 rejected by ip ratelimiting
00:42:47 unbound: [32538:0]  info: server stats for thread 0: requestlist max 1 avg 0.157895 exceeded 0 jostled 0
00:42:47 unbound: [32538:0]  info: average recursion processing time 1.652315 sec
00:42:47 unbound: [32538:0]  info: histogram of recursion processing times
00:42:47 unbound: [32538:0]  info: [25%]=0.85134 median[50%]=1.4375 [75%]=2.1
00:42:47 unbound: [32538:0]  info: lower(secs) upper(secs) recursions
00:42:47 unbound: [32538:0]  info:    0.131072    0.262144 1
00:42:47 unbound: [32538:0]  info:    0.262144    0.524288 1
00:42:47 unbound: [32538:0]  info:    0.524288    1.000000 4
00:42:47 unbound: [32538:0]  info:    1.000000    2.000000 8
00:42:47 unbound: [32538:0]  info:    2.000000    4.000000 5
00:42:47 unbound: [32538:0]  notice: Restart of unbound 1.19.0.
00:42:47 unbound: [32538:0]  notice: init module 0: respip
00:42:47 unbound: [32538:0]  notice: init module 1: validator
00:42:47 unbound: [32538:0]  notice: init module 2: iterator
00:42:53 unbound: [32538:0]  info: start of service (unbound 1.19.0).
00:47:55 unbound: [32538:0]  info: generate keytag query _ta-4a5c-4f66. NULL IN
01:12:48 unbound: [32538:0]  info: service stopped (unbound 1.19.0).
01:12:48 unbound: [32538:0]  info: server stats for thread 0: 111 queries, 46 answers from cache, 65 recursions, 3 prefetch, 0 rejected by ip ratelimiting
01:12:48 unbound: [32538:0]  info: server stats for thread 0: requestlist max 1 avg 0.161765 exceeded 0 jostled 0
01:12:48 unbound: [32538:0]  info: average recursion processing time 0.673840 sec
01:12:48 unbound: [32538:0]  info: histogram of recursion processing times
01:12:48 unbound: [32538:0]  info: [25%]=6.25e-07 median[50%]=0.216269 [75%]=0.988107
01:12:48 unbound: [32538:0]  info: lower(secs) upper(secs) recursions
01:12:48 unbound: [32538:0]  info:    0.000000    0.000001 26
01:12:48 unbound: [32538:0]  info:    0.131072    0.262144 10
01:12:48 unbound: [32538:0]  info:    0.262144    0.524288 3
01:12:48 unbound: [32538:0]  info:    0.524288    1.000000 10
01:12:48 unbound: [32538:0]  info:    1.000000    2.000000 10
01:12:48 unbound: [32538:0]  info:    2.000000    4.000000 6
01:12:48 unbound: [32538:0]  notice: Restart of unbound 1.19.0.
01:12:48 unbound: [32538:0]  notice: init module 0: respip
01:12:48 unbound: [32538:0]  notice: init module 1: validator
01:12:48 unbound: [32538:0]  notice: init module 2: iterator
01:12:54 unbound: [32538:0]  info: start of service (unbound 1.19.0).
01:12:54 unbound: [32538:0]  info: service stopped (unbound 1.19.0).
01:12:54 unbound: [32538:0]  info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
01:12:54 unbound: [32538:0]  info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
01:12:54 unbound: [32538:0]  notice: Restart of unbound 1.19.0.
01:12:54 unbound: [32538:0]  notice: init module 0: respip
01:12:54 unbound: [32538:0]  notice: init module 1: validator
01:12:54 unbound: [32538:0]  notice: init module 2: iterator
01:13:01 unbound: [32538:0]  info: start of service (unbound 1.19.0).
01:18:02 unbound: [32538:0]  info: generate keytag query _ta-4a5c-4f66. NULL IN
01:42:49 unbound: [32538:0]  info: service stopped (unbound 1.19.0).
01:42:49 unbound: [32538:0]  info: server stats for thread 0: 18 queries, 5 answers from cache, 13 recursions, 1 prefetch, 0 rejected by ip ratelimiting
01:42:49 unbound: [32538:0]  info: server stats for thread 0: requestlist max 2 avg 0.142857 exceeded 0 jostled 0
01:42:49 unbound: [32538:0]  info: average recursion processing time 1.032517 sec
01:42:49 unbound: [32538:0]  info: histogram of recursion processing times
01:42:49 unbound: [32538:0]  info: [25%]=0.458752 median[50%]=1.07143 [75%]=1.53571
01:42:49 unbound: [32538:0]  info: lower(secs) upper(secs) recursions
01:42:49 unbound: [32538:0]  info:    0.131072    0.262144 1
01:42:49 unbound: [32538:0]  info:    0.262144    0.524288 3
01:42:49 unbound: [32538:0]  info:    0.524288    1.000000 2
01:42:49 unbound: [32538:0]  info:    1.000000    2.000000 7
01:42:49 unbound: [32538:0]  notice: Restart of unbound 1.19.0.
01:42:49 unbound: [32538:0]  notice: init module 0: respip
01:42:49 unbound: [32538:0]  notice: init module 1: validator
01:42:49 unbound: [32538:0]  notice: init module 2: iterator
01:42:55 unbound: [32538:0]  info: start of service (unbound 1.19.0).

[bbitsch (Bernhard Bitsch)]

Which CU is installed?

[peppetech]

This one is a really old one, CU 182 oldie but goodie.

[bbitsch (Bernhard Bitsch)]

But with the problem of restarting unbound with (nearly) each DHCP lease renewal. See according discussions ( above ) and 13254 – CU 177 - LOTS of unbound restarts (1000s per week)

[peppetech]

Interesting. message log confirms there are DHCP renewals right before the restart
thank you for the hint

[bbitsch (Bernhard Bitsch)]

Another hint. the newest stable CU (187) has a modified unbound leases bridge, which reduces # the restarts to a minimum.

EDIT and correction:
The modified leases bridge is coming in Core Update 188, my fault.

[mumpitz]

I solved the problem by using the recursive DNS mode and eliminating a WLAN client that turned out to be a China bug

[tomikafelicitas]

Which CU??

[bonnietwin (Adolf Belka)]

Hallo @tomikafelicitas

Welcome to the IPFire community.

@tomikafelicitas

Which CU??

CU is an abbreviation for Core Update which is the update version of IPFire.

The current stable release version is Core Update 187.