Ubound logging + huge log file size

[sfxdude]

Hello
Yesterday my opensense box became unresponsive. On troubleshooting today I can see that for some reason, unbound has been filling the resolver log file in /var/log/resolver and yesterday managed to fill the entire disk (20GB). I'm not sure the root cause of this - my WAN may have gone down causing a large amount of DNS lookups but primarily I want to prevent this from happening again.
I do not have query logging turned on in Unbound advanced settings.
I can monitor the latest resolver log file and see that every query is logged and generates about 30 lines of log -

Code Select Expand

<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35856"] [5641:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35857"] [5641:0] info: validator operate: query time.google.com. A IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35858"] [5641:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35859"] [5641:0] info: resolving time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35860"] [5641:0] info: resolving (init part 2):  time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35861"] [5641:0] info: resolving (init part 3):  time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35862"] [5641:0] info: processQueryTargets: time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35863"] [5641:0] info: sending query: time.google.com. A IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35864"] [5641:0] debug: sending to target: <google.com.> 216.239.36.10#53
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35865"] [5641:0] debug: cache memory msg=156821 rrset=503779 infra=100404 val=116936
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35866"] [5641:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35867"] [5641:0] info: validator operate: query time.google.com. AAAA IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35868"] [5641:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35869"] [5641:0] info: resolving time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35870"] [5641:0] info: resolving (init part 2):  time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35871"] [5641:0] info: resolving (init part 3):  time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35872"] [5641:0] info: processQueryTargets: time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35873"] [5641:0] info: sending query: time.google.com. A IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35874"] [5641:0] debug: sending to target: <google.com.> 216.239.34.10#53
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35875"] [5641:0] debug: cache memory msg=156821 rrset=503779 infra=100404 val=116936
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35876"] [5641:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35877"] [5641:0] info: iterator operate: query time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35878"] [5641:0] info: response for time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35879"] [5641:0] info: reply from <google.com.> 216.239.36.10#53
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35880"] [5641:0] info: query response was ANSWER
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35881"] [5641:0] info: finishing processing for time.google.com. A IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35882"] [5641:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35883"] [5641:0] info: validator operate: query time.google.com. A IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35884"] [5641:0] info: NSEC3s for the referral proved no DS.
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35885"] [5641:0] info: Verified that unsigned response is INSECURE
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35886"] [5641:0] debug: cache memory msg=157030 rrset=504068 infra=100404 val=116936
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35887"] [5641:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35888"] [5641:0] info: iterator operate: query time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35889"] [5641:0] info: response for time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35890"] [5641:0] info: reply from <google.com.> 216.239.34.10#53
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35891"] [5641:0] info: query response was ANSWER
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35892"] [5641:0] info: processQueryTargets: time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35893"] [5641:0] info: sending query: time.google.com. AAAA IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35894"] [5641:0] debug: sending to target: <google.com.> 216.239.34.10#53
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35895"] [5641:0] debug: cache memory msg=157030 rrset=504068 infra=100404 val=116936
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35896"] [5641:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35897"] [5641:0] info: iterator operate: query time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35898"] [5641:0] info: response for time.google.com. AAAA IN
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35899"] [5641:0] info: reply from <google.com.> 216.239.34.10#53
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35900"] [5641:0] info: query response was ANSWER
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35901"] [5641:0] info: finishing processing for time.google.com. AAAA IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35902"] [5641:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
<30>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35903"] [5641:0] info: validator operate: query time.google.com. AAAA IN
<31>1 2022-04-11T13:43:55+01:00 firewall.lan unbound 5641 - [meta sequenceId="35904"] [5641:0] debug: cache memory msg=157239 rrset=504405 infra=100404 val=116936


How do I turn this off? How do I go about preventing unbound from filling the disk and bringing down my firewall when the WAN goes down?

[EdwinKM]

Have you verified the verbosity level of the log settings (Services -> Unbound DNS -> Advanced)

[sfxdude]

Thank you, it was set at 3, doh!