Topics

1

22.1 Legacy Series / WAN dropping - dhclient failing

« on: April 27, 2022, 02:47:08 pm »

Hi
I'm having some problems when the WAN drops. I use opnsense behind a cable modem in modem mode. The modem initially offers an address in the 192.168.100.x range before it has synced, which I have set to ignore. Eventually after sync, the modem passess through the DHCP offer from the upstream router.
However this fails sometimes, really not sure why, the logs are attached below. When it fails I lose internet until I force restart the dhclient or restart opnsense.

Code: [Select]

2022-04-27T01:44:30+01:00 firewall.lan dhclient[46125]: connection closed
2022-04-27T01:44:30+01:00 firewall.lan dhclient[46125]: exiting.
2022-04-27T01:44:34+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:35+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:36+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:37+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:38+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:40+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:44+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:44:51+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 1
2022-04-27T01:44:52+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:44:54+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 3
2022-04-27T01:44:57+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 6
2022-04-27T01:45:03+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 16
2022-04-27T01:45:09+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:10+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:12+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:15+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:19+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 7
2022-04-27T01:45:21+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 1
2022-04-27T01:45:22+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:45:24+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 4
2022-04-27T01:45:28+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 8
2022-04-27T01:45:36+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 10
2022-04-27T01:45:45+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:46+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:45:46+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:48+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 5
2022-04-27T01:45:48+01:00 firewall.lan dhclient[35471]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:45:53+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 36
2022-04-27T01:46:01+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:46:03+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:46:04+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:04+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:05+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:46:05+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:07+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 5
2022-04-27T01:46:07+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:12+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 5
2022-04-27T01:46:12+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:17+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 5
2022-04-27T01:46:17+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:22+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 8
2022-04-27T01:46:22+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:30+01:00 firewall.lan dhclient[35471]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 9
2022-04-27T01:46:30+01:00 firewall.lan dhclient[35471]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:34+01:00 firewall.lan dhclient[35471]: connection closed
2022-04-27T01:46:34+01:00 firewall.lan dhclient[35471]: exiting.
2022-04-27T01:46:36+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:36+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:37+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:37+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:38+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:38+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:39+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:39+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:40+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:40+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:41+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:41+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:43+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:43+01:00 firewall.lan dhclient[69198]: DHCPNACK from 192.168.100.1 rejected.
2022-04-27T01:46:48+01:00 firewall.lan dhclient[69198]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 1
2022-04-27T01:46:48+01:00 firewall.lan dhclient[69198]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:49+01:00 firewall.lan dhclient[69198]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:46:49+01:00 firewall.lan dhclient[69198]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:51+01:00 firewall.lan dhclient[69198]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 2
2022-04-27T01:46:51+01:00 firewall.lan dhclient[69198]: DHCPOFFER from 192.168.100.1 rejected.
2022-04-27T01:46:53+01:00 firewall.lan dhclient[69198]: DHCPDISCOVER on igb5 to 255.255.255.255 port 67 interval 3
2022-04-27T01:46:53+01:00 firewall.lan dhclient[69198]: DHCPOFFER from 10.53.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[69198]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T01:46:55+01:00 firewall.lan dhclient[69198]: DHCPACK from 10.53.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[11197]: New IP Address (igb5): 82.24.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[12157]: New Subnet Mask (igb5): 255.255.252.0
2022-04-27T01:46:55+01:00 firewall.lan dhclient[13096]: New Broadcast Address (igb5): 82.24.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[14363]: New Routers (igb5): 82.24.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[17786]: route add default 82.24.x.x
2022-04-27T01:46:55+01:00 firewall.lan dhclient[18984]: Creating resolv.conf
2022-04-27T01:48:37+01:00 firewall.lan dhclient[80309]: dhclient already running, pid: 68376.
2022-04-27T01:48:37+01:00 firewall.lan dhclient[80309]: exiting.
2022-04-27T07:32:15+01:00 firewall.lan dhclient[69164]: DHCPREQUEST on igb5 to 255.255.255.255 port 67
2022-04-27T07:32:15+01:00 firewall.lan dhclient[69164]: DHCPACK from 10.53.x.x
2022-04-27T07:32:15+01:00 firewall.lan dhclient[80040]: New IP Address (igb5): 82.24.x.x
2022-04-27T07:32:15+01:00 firewall.lan dhclient[81571]: New Subnet Mask (igb5): 255.255.252.0
2022-04-27T07:32:15+01:00 firewall.lan dhclient[82716]: New Broadcast Address (igb5): 82.24.x.x
2022-04-27T07:32:15+01:00 firewall.lan dhclient[83675]: New Routers (igb5): 82.24.x.x
2022-04-27T07:32:15+01:00 firewall.lan dhclient[88152]: route add default 82.24.x.x
2022-04-27T07:32:15+01:00 firewall.lan dhclient[89626]: Creating resolv.conf
2022-04-27T07:32:16+01:00 firewall.lan dhclient[69164]: bound to 82.24.x.x -- renewal in 245159 seconds.
Connection must have dropped at start of the logs (0144, I have nothing in the dhclient logs before this) and I rebooted opnsense at 0732. DHCP settings for the WAN interface are attached.

2

General Discussion / Ubound logging + huge log file size

« on: April 11, 2022, 02:45:26 pm »

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]

<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?