2.5.0.a.20210126.2350 unbound keeps stopping after upgrade
-
A little background, I've been running the 2.5.x code version for some time now, I usually update every few weeks to keep with the latest trends. After seeing that Wireguard support has been added I performed an upgrade last night and ran into some issues. Being that my network has a fair bit of complexity in it (multiple vlans, wireless controllers, etc) I thought that it might have been something in my installation causing the issues so I went through everything with a fine tooth comb and the only issue I could find was that unbound wasn't running, so I clicked to restart the service thought nothing of it and went to bed. Now my wife kids and I are all homebound due to covid so working from home has become essential. Having restarted the unbound service multiple times now including taking the pfSense box down at lunch to run the latest nightly upgrade (might not have been the right thing to do) still hasn't resolved this issue.
What follows are the logs between restarts:
2021-01-27 15:20:18.498232-06:00 unbound 25437 [25437:0] notice: Restart of unbound 1.13.0.
2021-01-27 15:20:18.496659-06:00 unbound 25437 [25437:0] info: server stats for thread 23: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.496642-06:00 unbound 25437 [25437:0] info: server stats for thread 23: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.494686-06:00 unbound 25437 [25437:0] info: server stats for thread 22: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.494669-06:00 unbound 25437 [25437:0] info: server stats for thread 22: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.492720-06:00 unbound 25437 [25437:0] info: server stats for thread 21: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.492702-06:00 unbound 25437 [25437:0] info: server stats for thread 21: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.490815-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 2
2021-01-27 15:20:18.490808-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.490800-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 1
2021-01-27 15:20:18.490792-06:00 unbound 25437 [25437:0] info: 0.032768 0.065536 1
2021-01-27 15:20:18.490785-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.490777-06:00 unbound 25437 [25437:0] info: [25%]=0.08192 median[50%]=0.196608 [75%]=0.360448
2021-01-27 15:20:18.490767-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.490759-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.205566 sec
2021-01-27 15:20:18.490751-06:00 unbound 25437 [25437:0] info: server stats for thread 20: requestlist max 1 avg 0.2 exceeded 0 jostled 0
2021-01-27 15:20:18.490734-06:00 unbound 25437 [25437:0] info: server stats for thread 20: 6 queries, 1 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.489170-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 2
2021-01-27 15:20:18.489162-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.489154-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 1
2021-01-27 15:20:18.489146-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.489139-06:00 unbound 25437 [25437:0] info: [25%]=0.131072 median[50%]=0.262144 [75%]=0.393216
2021-01-27 15:20:18.489128-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.489121-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.262651 sec
2021-01-27 15:20:18.489112-06:00 unbound 25437 [25437:0] info: server stats for thread 19: requestlist max 2 avg 0.5 exceeded 0 jostled 0
2021-01-27 15:20:18.489094-06:00 unbound 25437 [25437:0] info: server stats for thread 19: 4 queries, 0 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.487129-06:00 unbound 25437 [25437:0] info: server stats for thread 18: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.487112-06:00 unbound 25437 [25437:0] info: server stats for thread 18: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.485561-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.485554-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.485546-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.485537-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.485530-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.305086 sec
2021-01-27 15:20:18.485521-06:00 unbound 25437 [25437:0] info: server stats for thread 17: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.485504-06:00 unbound 25437 [25437:0] info: server stats for thread 17: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.483631-06:00 unbound 25437 [25437:0] info: server stats for thread 16: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.483614-06:00 unbound 25437 [25437:0] info: server stats for thread 16: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.481661-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.481653-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.481646-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.481637-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.481629-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.172042 sec
2021-01-27 15:20:18.481621-06:00 unbound 25437 [25437:0] info: server stats for thread 15: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.481604-06:00 unbound 25437 [25437:0] info: server stats for thread 15: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.479612-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 2
2021-01-27 15:20:18.479604-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.479597-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.479587-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.479580-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.094547 sec
2021-01-27 15:20:18.479572-06:00 unbound 25437 [25437:0] info: server stats for thread 14: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.479555-06:00 unbound 25437 [25437:0] info: server stats for thread 14: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.477596-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 1
2021-01-27 15:20:18.477588-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.477580-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.477571-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.477563-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.111425 sec
2021-01-27 15:20:18.477555-06:00 unbound 25437 [25437:0] info: server stats for thread 13: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.477537-06:00 unbound 25437 [25437:0] info: server stats for thread 13: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.475441-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.475434-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.475426-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.475417-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.475410-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.407732 sec
2021-01-27 15:20:18.475401-06:00 unbound 25437 [25437:0] info: server stats for thread 12: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.475384-06:00 unbound 25437 [25437:0] info: server stats for thread 12: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.473504-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 1
2021-01-27 15:20:18.473497-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.473489-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.473480-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.473473-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.084062 sec
2021-01-27 15:20:18.473464-06:00 unbound 25437 [25437:0] info: server stats for thread 11: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.473447-06:00 unbound 25437 [25437:0] info: server stats for thread 11: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.471910-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.471902-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.471894-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.471887-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.471878-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.471870-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.247870 sec
2021-01-27 15:20:18.471862-06:00 unbound 25437 [25437:0] info: server stats for thread 10: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.471845-06:00 unbound 25437 [25437:0] info: server stats for thread 10: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.470282-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.470275-06:00 unbound 25437 [25437:0] info: 0.032768 0.065536 1
2021-01-27 15:20:18.470267-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.470260-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.470250-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.470243-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.152632 sec
2021-01-27 15:20:18.470235-06:00 unbound 25437 [25437:0] info: server stats for thread 9: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.470219-06:00 unbound 25437 [25437:0] info: server stats for thread 9: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.468239-06:00 unbound 25437 [25437:0] info: server stats for thread 8: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.468222-06:00 unbound 25437 [25437:0] info: server stats for thread 8: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.466121-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.466113-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.466106-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.466097-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.466090-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.334394 sec
2021-01-27 15:20:18.466081-06:00 unbound 25437 [25437:0] info: server stats for thread 7: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.466065-06:00 unbound 25437 [25437:0] info: server stats for thread 7: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.464499-06:00 unbound 25437 [25437:0] info: 0.524288 1.000000 1
2021-01-27 15:20:18.464491-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.464483-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.464474-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.464467-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.563145 sec
2021-01-27 15:20:18.464458-06:00 unbound 25437 [25437:0] info: server stats for thread 6: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.464441-06:00 unbound 25437 [25437:0] info: server stats for thread 6: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.462480-06:00 unbound 25437 [25437:0] info: server stats for thread 5: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.462463-06:00 unbound 25437 [25437:0] info: server stats for thread 5: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.460515-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.460507-06:00 unbound 25437 [25437:0] info: 0.065536 0.131072 1
2021-01-27 15:20:18.460499-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.460491-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.460482-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.460475-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.259526 sec
2021-01-27 15:20:18.460466-06:00 unbound 25437 [25437:0] info: server stats for thread 4: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.460449-06:00 unbound 25437 [25437:0] info: server stats for thread 4: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.458704-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.458696-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.458689-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.458679-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.458672-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.272550 sec
2021-01-27 15:20:18.458663-06:00 unbound 25437 [25437:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.458647-06:00 unbound 25437 [25437:0] info: server stats for thread 3: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.457065-06:00 unbound 25437 [25437:0] info: 0.524288 1.000000 1
2021-01-27 15:20:18.457058-06:00 unbound 25437 [25437:0] info: 0.262144 0.524288 1
2021-01-27 15:20:18.457051-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.457043-06:00 unbound 25437 [25437:0] info: 0.032768 0.065536 1
2021-01-27 15:20:18.457035-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.457028-06:00 unbound 25437 [25437:0] info: [25%]=0.065536 median[50%]=0.262144 [75%]=0.524288
2021-01-27 15:20:18.457017-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.457010-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.300862 sec
2021-01-27 15:20:18.457001-06:00 unbound 25437 [25437:0] info: server stats for thread 2: requestlist max 2 avg 0.5 exceeded 0 jostled 0
2021-01-27 15:20:18.456981-06:00 unbound 25437 [25437:0] info: server stats for thread 2: 6 queries, 2 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.454977-06:00 unbound 25437 [25437:0] info: 0.131072 0.262144 1
2021-01-27 15:20:18.454969-06:00 unbound 25437 [25437:0] info: lower(secs) upper(secs) recursions
2021-01-27 15:20:18.454962-06:00 unbound 25437 [25437:0] info: [25%]=0 median[50%]=0 [75%]=0
2021-01-27 15:20:18.454952-06:00 unbound 25437 [25437:0] info: histogram of recursion processing times
2021-01-27 15:20:18.454945-06:00 unbound 25437 [25437:0] info: average recursion processing time 0.206375 sec
2021-01-27 15:20:18.454936-06:00 unbound 25437 [25437:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.454920-06:00 unbound 25437 [25437:0] info: server stats for thread 1: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.453264-06:00 unbound 25437 [25437:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-01-27 15:20:18.453243-06:00 unbound 25437 [25437:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-01-27 15:20:18.451387-06:00 unbound 25437 [25437:0] info: service stopped (unbound 1.13.0).
2021-01-27 15:19:40.082221-06:00 unbound 25437 [25437:3] info: generate keytag query _ta-4f66. NULL IN
2021-01-27 15:19:39.945843-06:00 unbound 25437 [25437:15] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.945629-06:00 unbound 25437 [25437:17] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944719-06:00 unbound 25437 [25437:0] info: start of service (unbound 1.13.0).
2021-01-27 15:19:39.944702-06:00 unbound 25437 [25437:d] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944672-06:00 unbound 25437 [25437:16] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944646-06:00 unbound 25437 [25437:0] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944490-06:00 unbound 25437 [25437:10] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944461-06:00 unbound 25437 [25437:7] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944428-06:00 unbound 25437 [25437:14] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944406-06:00 unbound 25437 [25437:c] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944376-06:00 unbound 25437 [25437:a] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944344-06:00 unbound 25437 [25437:12] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944318-06:00 unbound 25437 [25437:f] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944288-06:00 unbound 25437 [25437:e] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944257-06:00 unbound 25437 [25437:6] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944215-06:00 unbound 25437 [25437:4] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944169-06:00 unbound 25437 [25437:8] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944123-06:00 unbound 25437 [25437:11] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944089-06:00 unbound 25437 [25437:13] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944061-06:00 unbound 25437 [25437:2] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.944011-06:00 unbound 25437 [25437:b] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.943984-06:00 unbound 25437 [25437:5] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.943909-06:00 unbound 25437 [25437:9] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.943805-06:00 unbound 25437 [25437:1] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.943629-06:00 unbound 25437 [25437:3] error: duplicate forward zone . ignored.
2021-01-27 15:19:39.931217-06:00 unbound 25437 [25437:0] notice: init module 1: iterator
2021-01-27 15:19:39.930161-06:00 unbound 25437 [25437:0] notice: init module 0: validator
2021-01-27 15:19:39.927373-06:00 unbound 25437 [25437:0] notice: Restart of unbound 1.13.0.Any help or assistance would be greatly appreciated as I don't really want to factory reset and go through a fresh setup again.
Sincerely, J
-
Be aware : I'm not using 2.5.0 as I need a stable environment - for the same reasons as you mentioned.
Simplicity is also preferred over complexity.As you can see, at 15:19:39 it receives a restart.
=> What / who triggered that restart ? Use the logs to find out.error: duplicate forward zone . ignored.What are your unbound settings ? Complex, or not : make them go away.
Then the 20 ( ??) threads have to get killed - and while doing so, stats are logged. But really : 20 threads ? Maybe that's normal for unbound 1.13.0 unbound, or do you really have that many cores ?
After the restart, the start shows up :
15:19:39.944719-06:00 unbound 25437 [25437:0] info: start of service (unbound 1.13.0).to get stopped less then 40 seconds later ?
15:20:18.451387-06:00 unbound 25437 [25437:0] info: service stopped (unbound 1.13.0).go logs to find the why part.
Now all the stats are shown.
And while doing so, it receives another restart :15:20:18.498232-06:00 unbound 25437 [25437:0] notice: Restart of unbound 1.13.0.So, right, very true, this is going no where.
Did I mention to see the other logs, so you can tell us what is happening ?What happens in the DHCP log ?
Maybe not related, as this is 2.5.0 : 2.4.5-p1 restart unbound on every DHCP request/renew : you'll be needing just one device on your LAN(s) that renews it lease every second and unbound gets restarted every second : your DNS will go ko / play dead.
But : with the click on a button on the right place (unbound settings page) - and the help of one of the thousand times it's already explained in this forum - for the why part, it's easy to stop this from happening. -
For whatever it is worth, I installed 2.5.0.r.20210209.1125 last night and I'm seeing the same thing. I set up the service watchdog package and I have a dozen notes about Unbound being restarted.
Happy to pull logs or whatever if needed, I'm not really clear what else is needed at this stage.
-
@thedaveca
Disable the watchdog thing.
Look at the logs : you'll probably see that unbound is started, more precise : it is actually restarted which means it's stopped first (it isn't dying or so) and then started.
Some other process is doing that.
Your mission : what process ? Then you'll be close to the solution. -
@gertjan without Watchdog I simply have no DNS. With it, at least DNS comes back promptly, and I can see the frequency of the failures. It is multiple times an hour, but not yet predictable.
It does seem to shut down at the request of something, but how to determine what?
-
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
but how to determine what?
By comparing several logs - checking what happens at the moment - or a second or so before that - when unbound is told to stop.
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
without Watchdog I simply have no DNS
You mean, you see :
Feb 8 08:44:37 unbound 99631:0 info: service stopped (unbound 1.x.y).and it never starts again ? Or tries to ?
A 'stop' is always coupled with a 'start' - on my system, 3 seconds later, shown here :
Feb 8 08:44:40 unbound 79395:0 info: start of service (unbound 1.x.y).Between the stop and start, unbound dumps 20 lines (or so) simple statistics.
-
@gertjan It doesn't manage to start again, I'll check the logs next time I'm in the office to see if it attempts to start.
Either way, constantly needlessly restarting is still an issue that needs to be resolved as this will, in the best case, cause a momentary outage and discard the entire DNS cache.
Needlessly is obviously an assumption, if there were an IP or network configuration change or something else there could be a trigger, but based on the frequency it is happening, I don't suspect that this is the situation here. If nothing else, I am MultiWAN with static IPs on all interfaces.
-
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
with static IPs on all interfaces.
That permits an easy test : stop the DHCP server on all interfaces.
Imagine this : if you have a device on a network exists that chain-guns the (a) DHCP server with DHCP requests, you see exactly what you're seeingg now : unbound getting hupped x times per minute or worse, per second.Also : check the main log if there is an interface that fires constant LINK DOWN - LINK UP - .....
If you can take the network down a minute or so :
Use the console access, and check if unbound is running.
Remove one by one all interfaces, until a stable situation is reached. Put them back, untill unbound starts 'stopping' again.If unbound stops without any networks present .... well, that would be something new.
t.
-
@thedaveca Are you running DNSBL/pfBlockerNG ? There is a known bug that causes unbound to restart if you have DHCP Registration enabled in the DNS Resolver settings page.
-
@ab5g I do have DHCP registrations enabled, but I do not use DNSBL/pfBlockerNG.
-
@ab5g said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
There is a known bug that causes unbound to restart if you have DHCP Registration enabled in the DNS Resolver settings page.
A 2.4.5-p1 issue.
Not a bug.
If you want unbound to get restarted (or reloaded) when a new lease comes in, and (see above) you added a "brain dead device" that emits a lot of DHCP-renews or DHCP-requests, then you get what you asked for.What is the relation with pfBlockerNG ? If you set the cron update to every minute or so then yes, unbound can gets kicked around also. Again : what you asked for.
On systems with 'all default settings', unbound doesn't get restarted (often).
Not to forget : this is bleeding edge technology (== beta) as it concerns 2.5.0.xxxx
-
-
Failing to start again is a bug.
-
Shutting down at all for routine updates is a bug, instead use unbound-control to update the needed record/zone/whatever.
-
What brain-dead device? I have ~100 leases active, depending on the day, sometimes including a public wifi. Losing DNS service for a short period and dumping the entire cache every time a DHCP client is assigned an IP is absolutely a bug, even if the restart worked.
And yes, it’s a beta. I run the beta to find issues, and get comfortable before I am in a position to be supporting something in front of a client. I’m comfortable with the instability risks of beta platforms.
-
-
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
Failing to start again is a bug.
True.
But I like to add : it would be a fail if there is not a reason logged why it failed. It always does.@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
routine updates is a bug
as mentioned in other threads (right now) : the update tree is redone .....
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
What brain-dead device? I have ~100 leases active,
and you have the resolver restarted at every incoming lease ?
This option still exists in 2.5.0 :
?
If so, disable it and check.
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
And yes, it’s a beta. I run the beta to find issues, and get comfortable before I am in a position to be supporting something in front of a client. I’m comfortable with the instability risks of beta platforms.
Thanks for that ! -
and you have the resolver restarted at every incoming lease ?
This option still exists in 2.5.0 :
?
If so, disable it and check.
No, I have the option to register DHCP leases enabled, nothing implies any need to shut down the service. unbound-control should be used to reload the record/zone on the fly.
Under temporarily disabled the option to test, I won’t know until the morning.
-
@thedaveca said in 2.5.0.a.20210126.2350 unbound keeps stopping after upgrade:
nothing implies any need to shut down the service
Check out the history of this box checked on this forum.
Hundreds of posts (issues) will argue that it's close to 'mandatory'.No service will get shut down. But DHCP clients that do not have a static MAC lease won't get their device name registered (if they even have one) into the DNS.
And unbound will thank you for that.That is, this was the "2.4.5-p1" solution.
Recently, I found out that, with 2.5.0 , which is using a newer unbound versionit will get hupped (send a signal called HUP) : and that it behaves diffreently. It shouldn't restart any more on DHCP events. So up to you to discover the reason.
The answers will be / should be in the logs.
