Unbound restarts, per monit, several times a day (actually more)

[Linwood]

I recently upgraded from 23.1.11 from 22.mumble, and everything seems to work except that unbound seems to stop multiple times a day.

I say "seems" as it is monit reporting it.  It is configured as in the attached screen shots. This worked in the earlier version in that it would detect the service stopped, would restart it, but rarely gave any such indication.

Now multiple times a day I get a restarted indication.

I found the following in the log, notice the service started at 5:10 then almost to the second an hour later it shows stopped.  I can see no errors.

Code: [Select]

<30>1 2023-07-02T05:10:27-04:00 OPNsense.leferguson.com unbound 17627 - [meta sequenceId="55"] [17627:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T06:10:25-04:00 OPNsense.leferguson.com unbound 17627 - [meta sequenceId="1"] [17627:0] info: service stopped (unbound 1.17.1).
<30>1 2023-07-02T06:10:25-04:00 OPNsense.leferguson.com unbound 17627 - [meta sequenceId="2"] [17627:0] info: server stats for thread 0: 494 queries, 357 answers from cache, 137 recursions, 106 prefetch, 0 rejected by ip ratelimiting
<30>1 2023-07-02T06:10:25-04:00 OPNsense.leferguson.com unbound 17627 - [meta sequenceId="3"] [17627:0] info: server stats for thread 0: requestlist max 2 avg 0.168724 exceeded 0 jostled 0

It almost makes me wonder if unbound is automatically restarting and monit is only fast enough to see it some times.  There are a LOT of restarts, here's just todays:

Code: [Select]

root@OPNsense:/var/log # cat /var/log/resolver/resolver_20230702.log | grep "start of service"
<30>1 2023-07-02T00:31:16-04:00 OPNsense.leferguson.com unbound 99629 - [meta sequenceId="58"] [99629:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T00:38:15-04:00 OPNsense.leferguson.com unbound 57575 - [meta sequenceId="54"] [57575:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T01:38:15-04:00 OPNsense.leferguson.com unbound 32669 - [meta sequenceId="60"] [32669:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T01:47:40-04:00 OPNsense.leferguson.com unbound 95744 - [meta sequenceId="55"] [95744:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T02:47:40-04:00 OPNsense.leferguson.com unbound 46168 - [meta sequenceId="60"] [46168:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T02:54:21-04:00 OPNsense.leferguson.com unbound 94883 - [meta sequenceId="54"] [94883:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T03:54:22-04:00 OPNsense.leferguson.com unbound 26459 - [meta sequenceId="59"] [26459:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T03:59:17-04:00 OPNsense.leferguson.com unbound 89082 - [meta sequenceId="51"] [89082:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T03:59:24-04:00 OPNsense.leferguson.com unbound 22148 - [meta sequenceId="86"] [22148:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T04:59:18-04:00 OPNsense.leferguson.com unbound 59131 - [meta sequenceId="60"] [59131:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T05:10:27-04:00 OPNsense.leferguson.com unbound 17627 - [meta sequenceId="55"] [17627:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T06:10:27-04:00 OPNsense.leferguson.com unbound 52214 - [meta sequenceId="59"] [52214:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T06:10:33-04:00 OPNsense.leferguson.com unbound 90178 - [meta sequenceId="97"] [90178:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T06:13:56-04:00 OPNsense.leferguson.com unbound 75696 - [meta sequenceId="54"] [75696:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T07:13:56-04:00 OPNsense.leferguson.com unbound 34947 - [meta sequenceId="62"] [34947:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T07:22:13-04:00 OPNsense.leferguson.com unbound 63457 - [meta sequenceId="57"] [63457:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T08:22:12-04:00 OPNsense.leferguson.com unbound 23765 - [meta sequenceId="62"] [23765:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T08:31:07-04:00 OPNsense.leferguson.com unbound 76284 - [meta sequenceId="57"] [76284:0] info: start of service (unbound 1.17.1).
<30>1 2023-07-02T09:31:07-04:00 OPNsense.leferguson.com unbound 98578 - [meta sequenceId="63"] [98578:0] info: start of service (unbound 1.17.1).


It appears up often enough to work, but what is going on?   I can't see anything in the log that indicates a reason for it to have stopped (or started in the non-monit detected cases).

I am unsure where I can look, the only thing I changed was the upgrade.

Linwood

[Linwood]

I decided to see how often it was restarting before since I saw the logs went back quite far.  The short answer is not at all really.  On 5/2 there are a few restarts but that is when I apparently upgraded some items (notice unbound goes from 1.17.0 to 1.17.1) then once on 5/10 (maybe power failure?) then not again until I did the upgrade, which i did on 6/28 and it started the many restarts per day (I only show the first few but they continue each day to present):

Code: [Select]

root@OPNsense:/etc # grep "start of service" /var/log/resolver/resolver_2023*
/var/log/resolver/resolver_20230214.log:<30>1 2023-02-14T20:24:24-05:00 OPNsense.leferguson.com unbound 14728 - [meta sequenceId="108"] [14728:0] info: start of service (unbound 1.17.0).
/var/log/resolver/resolver_20230502.log:<30>1 2023-05-02T11:16:51-04:00 OPNsense.leferguson.com unbound 4021 - [meta sequenceId="5"] [4021:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230502.log:<30>1 2023-05-02T11:17:45-04:00 OPNsense.leferguson.com unbound 87509 - [meta sequenceId="6"] [87509:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230502.log:<30>1 2023-05-02T11:17:55-04:00 OPNsense.leferguson.com unbound 99213 - [meta sequenceId="61"] [99213:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230510.log:<30>1 2023-05-10T19:00:22-04:00 OPNsense.leferguson.com unbound 53262 - [meta sequenceId="99"] [53262:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230628.log:<30>1 2023-06-28T01:43:47-04:00 OPNsense.leferguson.com unbound 69128 - [meta sequenceId="118"] [69128:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230628.log:<30>1 2023-06-28T01:44:54-04:00 OPNsense.leferguson.com unbound 22 - [meta sequenceId="179"] [22:0] info: start of service (unbound 1.17.1).
/var/log/resolver/resolver_20230628.log:<30>1 2023-06-28T02:08:53-04:00 OPNsense.leferguson.com unbound 13803 - [meta sequenceId="72"] [13803:0] info: start of service (unbound 1.17.1).


[Linwood]

No one?

Does Unbound not restart for others?