DNS Stalling?

[Visseroth]

Still nothing huh?

The problem still persists. I've been watching the DNS logs closer and I've found that periodically the server restarts. It stops then starts again which explains why DNS becomes unavailable on the network then becomes available again.

Having DNS Feeds makes the problem worse. Causing the service to restart every half hour or so.

[Visseroth]

Feb 23 03:38:59 	unbound 	38470:0 	info: start of service (unbound 1.6.6).
Feb 23 03:38:59 	unbound 	38470:0 	notice: init module 1: iterator
Feb 23 03:38:59 	unbound 	38470:0 	notice: init module 0: validator
Feb 23 03:38:59 	unbound 	38470:0 	notice: Restart of unbound 1.6.6.
Feb 23 03:38:59 	unbound 	38470:0 	info: 2.000000 4.000000 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 3
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 9
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 14
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 13
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 5
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.0970437 median[50%]=0.173202 [75%]=0.313116
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.299957 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 7: requestlist max 6 avg 0.294118 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 7: 160 queries, 115 answers from cache, 45 recursions, 6 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 3
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 4
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.12288 median[50%]=0.212992 [75%]=0.371371
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.258216 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 6: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 6: 58 queries, 47 answers from cache, 11 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 3
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 3
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 3
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.016384 0.032768 1
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.0600747 median[50%]=0.131072 [75%]=0.32768
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.244966 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 5: requestlist max 1 avg 0.0625 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 5: 50 queries, 36 answers from cache, 14 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 1.000000 2.000000 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 4
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 11
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 15
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 11
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 3
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.114688 median[50%]=0.205346 [75%]=0.375343
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.261052 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 4: requestlist max 10 avg 0.642857 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 4: 138 queries, 93 answers from cache, 45 recursions, 11 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 6
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 6
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 5
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.117965 median[50%]=0.218453 [75%]=0.393216
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.261350 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 3: requestlist max 1 avg 0.0769231 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 3: 88 queries, 68 answers from cache, 20 recursions, 6 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 5
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.0753664 median[50%]=0.111411 [75%]=0.212992
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.181392 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 2: 22 queries, 11 answers from cache, 11 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 1.000000 2.000000 1
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 5
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 12
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 10
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 8
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 5
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.108544 median[50%]=0.229376 [75%]=0.431445
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.294336 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 1: requestlist max 9 avg 0.468085 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 1: 131 queries, 90 answers from cache, 41 recursions, 6 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.524288 1.000000 2
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.262144 0.524288 10
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.131072 0.262144 10
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.065536 0.131072 8
Feb 23 03:38:59 	unbound 	38470:0 	info: 0.032768 0.065536 3
Feb 23 03:38:59 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:38:59 	unbound 	38470:0 	info: [25%]=0.108544 median[50%]=0.203162 [75%]=0.360448
Feb 23 03:38:59 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:38:59 	unbound 	38470:0 	info: average recursion processing time 0.220479 sec
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 0: requestlist max 1 avg 0.0454545 exceeded 0 jostled 0
Feb 23 03:38:59 	unbound 	38470:0 	info: server stats for thread 0: 117 queries, 84 answers from cache, 33 recursions, 11 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:38:59 	unbound 	38470:0 	info: service stopped (unbound 1.6.6).
Feb 23 03:24:18 	unbound 	38470:0 	info: start of service (unbound 1.6.6).
Feb 23 03:24:18 	unbound 	38470:0 	notice: init module 1: iterator
Feb 23 03:24:18 	unbound 	38470:0 	notice: init module 0: validator
Feb 23 03:24:18 	unbound 	38470:0 	notice: Restart of unbound 1.6.6.
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 4
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 6
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.000000 0.000001 1
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.0950272 median[50%]=0.16384 [75%]=0.256683
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.203125 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 7: requestlist max 2 avg 0.137931 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 7: 802 queries, 785 answers from cache, 17 recursions, 12 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 6
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.0884736 median[50%]=0.141995 [75%]=0.223915
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.179679 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 6: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 6: 437 queries, 422 answers from cache, 15 recursions, 6 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 13
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 14
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 10
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.016384 0.032768 1
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.11305 median[50%]=0.201289 [75%]=0.337762
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.226305 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 5: requestlist max 1 avg 0.0266667 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 5: 1349 queries, 1308 answers from cache, 41 recursions, 34 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 1.000000 2.000000 2
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 4
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 12
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 4
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 7
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.090112 median[50%]=0.196608 [75%]=0.393216
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.293839 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 4: requestlist max 6 avg 0.308642 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 4: 1553 queries, 1519 answers from cache, 34 recursions, 47 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 1.000000 2.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 11
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 14
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 10
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.000000 0.000001 1
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.103219 median[50%]=0.201289 [75%]=0.387258
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.259413 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 3: requestlist max 12 avg 0.257732 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 3: 1924 queries, 1877 answers from cache, 47 recursions, 50 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 11
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 12
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 14
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 11
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 5
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.000000 0.000001 1
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.11022 median[50%]=0.224695 [75%]=0.469675
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.270860 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 2: requestlist max 6 avg 0.712766 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 2: 1936 queries, 1882 answers from cache, 54 recursions, 40 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 1.000000 2.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.262144 0.524288 7
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.131072 0.262144 7
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 11
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 3
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.0923462 median[50%]=0.149797 [75%]=0.318318
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.234704 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 1: requestlist max 2 avg 0.102941 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 1: 1043 queries, 1013 answers from cache, 30 recursions, 38 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.065536 0.131072 3
Feb 23 03:24:18 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:24:18 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:24:18 	unbound 	38470:0 	info: [25%]=0.0709973 median[50%]=0.098304 [75%]=0.125611
Feb 23 03:24:18 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:24:18 	unbound 	38470:0 	info: average recursion processing time 0.188230 sec
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 23 03:24:18 	unbound 	38470:0 	info: server stats for thread 0: 55 queries, 50 answers from cache, 5 recursions, 3 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:24:18 	unbound 	38470:0 	info: service stopped (unbound 1.6.6).
Feb 23 03:06:22 	unbound 	38470:0 	info: start of service (unbound 1.6.6).
Feb 23 03:06:22 	unbound 	38470:0 	notice: init module 1: iterator
Feb 23 03:06:22 	unbound 	38470:0 	notice: init module 0: validator
Feb 23 03:06:22 	unbound 	38470:0 	notice: Restart of unbound 1.6.6.
Feb 23 03:06:22 	unbound 	38470:0 	info: 4.000000 8.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 2.000000 4.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 4
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 2
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 5
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 3
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.137626 median[50%]=0.249037 [75%]=0.732412
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.741498 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 7: requestlist max 15 avg 1.68421 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 7: 187 queries, 170 answers from cache, 17 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 2
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 4
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 8
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.083968 median[50%]=0.118784 [75%]=0.221184
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.176934 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 6: requestlist max 1 avg 0.0526316 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 6: 236 queries, 219 answers from cache, 17 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 1.000000 2.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 2
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 4
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 3
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.0928427 median[50%]=0.180224 [75%]=0.360448
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.349986 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 5: requestlist max 8 avg 1.15385 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 5: 80 queries, 67 answers from cache, 13 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 2.000000 4.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 3
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 1
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.141995 median[50%]=0.196608 [75%]=0.251221
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.832805 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 4: requestlist max 2 avg 0.375 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 4: 117 queries, 112 answers from cache, 5 recursions, 3 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 1.000000 2.000000 3
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 2
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 9
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 7
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 7
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.016384 0.032768 1
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.110007 median[50%]=0.234057 [75%]=0.444188
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.325644 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 3: requestlist max 32 avg 2.70968 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 3: 265 queries, 234 answers from cache, 31 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 1.000000 2.000000 9
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 5
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 12
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 5
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 6
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 2
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.176947 median[50%]=0.404139 [75%]=0.928643
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.529838 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 2: requestlist max 36 avg 5.5814 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 2: 282 queries, 243 answers from cache, 39 recursions, 4 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 4
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 6
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.065536 0.131072 7
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.016384 0.032768 1
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.000000 0.000001 1
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.0866011 median[50%]=0.141995 [75%]=0.256683
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.177045 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 1: requestlist max 1 avg 0.173913 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 1: 237 queries, 216 answers from cache, 21 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:22 	unbound 	38470:0 	info: 2.000000 4.000000 5
Feb 23 03:06:22 	unbound 	38470:0 	info: 1.000000 2.000000 50
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.524288 1.000000 5
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.262144 0.524288 7
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.131072 0.262144 26
Feb 23 03:06:22 	unbound 	38470:0 	info: 0.032768 0.065536 1
Feb 23 03:06:22 	unbound 	38470:0 	info: lower(secs) upper(secs) recursions
Feb 23 03:06:22 	unbound 	38470:0 	info: [25%]=0.2445 median[50%]=1.16 [75%]=1.63
Feb 23 03:06:22 	unbound 	38470:0 	info: histogram of recursion processing times
Feb 23 03:06:22 	unbound 	38470:0 	info: average recursion processing time 0.885568 sec
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 0: requestlist max 35 avg 19.3684 exceeded 0 jostled 0
Feb 23 03:06:22 	unbound 	38470:0 	info: server stats for thread 0: 121 queries, 27 answers from cache, 94 recursions, 1 prefetch, 0 rejected by ip ratelimiting
Feb 23 03:06:15 	unbound 	38470:0 	info: service stopped (unbound 1.6.6)

[Grimson]

https://forum.pfsense.org/index.php?topic=130696.msg785999#msg785999

[Visseroth]

Thanks

As for the first error posted. I did find a answer to that one for anyone else looking. The Outgoing interfaces for DNS needs to be set to "ALL". Incoming can be set to your explicit local LAN interfaces. Whatever they may be.

[johnpoz]

"The Outgoing interfaces for DNS needs to be set to "ALL"."

No it doesn't.. I have zero issues with my unbound and the only outbound interface is WAN

[Visseroth]

Interesting, because when I tried to do that the error came back. When I set to ALL it stopped spamming errors

[johnpoz]

Did you see this Thread

https://forum.pfsense.org/index.php?topic=137656.0

Do you have link local also selected when your selecting wan?

[Visseroth]

Yep, which is why I re-set the outgoing interface back to the default "All" which shouldn't allow any internal quiries to go outside the firewall. The firewall will answer what it can and inquire about anything it doesn't know while not answering any DNS inquiries publically.
Since making the changes to "All" on the outgoing and only selecting what networks I want the DNS to answer to on the "Network Interfaces", the logs stopped spamming.

Anyhow, point is, both problems have been solved, though posted in the same thread they have been figured out.

[johnpoz]

"back to the default "All" which shouldn't allow any internal quiries to go outside the firewall."

What?  How is that?

Did you change your zone type?  The zone type of transparent would mean if you ask for something that is in your internal domain and there is no record, it will query upstream for it.

[Visseroth]

Exactly! and maybe I'm not being transparent myself, so being a picture is worth a thousand words here you go…


[johnpoz]

So your transparent… So if you query for something.yourdomain.tld and there is no something.yourdomain.tld then yes unbound will look for that upstream..

If you do not want unbound to look upstream for something when there is NO something then you need to change your zone type to static..

ah where your problem is your listening on link local... Why?  You stated your not even using ipv6... Uncheck those on your listen side and then set your outgoing to wan only and bet your log spam goes away.

[Visseroth]

wouldn't that also keep DNS from inquiring about web domains?

[johnpoz]

huh??  No static is only for your local domain!!

Look at unbound conf doc
https://www.unbound.net/documentation/unbound.conf.html

static
                If there is a match from local data, the query  is  answered.
                Otherwise,  the  query  is  answered with nodata or nxdomain.
                For a negative answer a SOA is  included  in  the  answer  if
                present as local-data for the zone apex domain.

transparent
                If  there  is a match from local data, the query is answered.
                Otherwise if the query has a different  name,  the  query  is
                resolved  normally.  If  the  query  is  for a name given in
                localdata but no such type of data  is  given  in  localdata,
                then  a  noerror nodata answer is returned.  If no local-zone
                is given local-data causes a transparent zone to  be  created
                by default.

[Visseroth]

Interesting. I'll toy with it, can't say I completely understand it.

[johnpoz]

So here look set to static I ask for something.local.lan, which there is no record of that I get back this..

dig something.local.lan

; <<>> DiG 9.11.2-P1 <<>> something.local.lan                         
;; global options: +cmd                                               
;; Got answer:                                                         
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 21582             
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:                                                 
; EDNS: version: 0, flags:; udp: 4096                                 
;; QUESTION SECTION:                                                   
;something.local.lan.          IN      A

;; Query time: 0 msec                                                 
;; SERVER: 192.168.9.253#53(192.168.9.253)                             
;; WHEN: Sat Feb 24 03:18:29 Central Standard Time 2018               
;; MSG SIZE  rcvd: 48

It sends the NX… And thing else happens... Now if change the zone to transparent which is the default..  You get this instead..

dig something.local.lan

; <<>> DiG 9.11.2-P1 <<>> something.local.lan
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 37322
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;something.local.lan.          IN      A

;; AUTHORITY SECTION:
.                      3600    IN      SOA  **  a.root-servers.net**. nstld.verisign-grs.com. 2018022400 1800 900 604800 86400

;; Query time: 179 msec
;; SERVER: 192.168.9.253#53(192.168.9.253)
;; WHEN: Sat Feb 24 03:19:44 Central Standard Time 2018
;; MSG SIZE  rcvd: 123

It tried to find that by normal resolve.. You can see roots sent back hey buddy sorry no .lan network… If you would sniff on wan you would see it asking for that.. I did query for othersomething since something was cached as neg and wouldn't go ask again until that neg ttl expired..