Messages

Not sure this has anything to do with dynamic IPs with me - my IP has not changed for several years.

Just rebooted my modem, exactly the same as last time, and the problem remains. Last few lines of the dhclient log file are as follows:

Code Select Expand

2022-06-14T16:36:32+01:00 firewall.lan dhclient[48130]: dhclient already running, pid: 31342.
2022-06-14T16:36:32+01:00 firewall.lan dhclient[48130]: exiting.
2022-06-14T16:37:07+01:00 firewall.lan dhclient[27026]: dhclient already running, pid: 31342.
2022-06-14T16:37:07+01:00 firewall.lan dhclient[27026]: exiting.
2022-06-14T16:37:42+01:00 firewall.lan dhclient[75539]: dhclient already running, pid: 31342.
2022-06-14T16:37:42+01:00 firewall.lan dhclient[75539]: exiting.

Absolutely nothing else in the dhclient log relating to this loss of WAN, and the WAN never comes back, presumably because the dhclient has crashed / failed somehow. Any help appreciated.

I'm not really sure. I just tried rebooting my modem and it behaved as expected (opnsense got a new external IP after rejecting the internal IP initially) so I'm not sure if this is due to some update or if the issue was unrelated.

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 Expand

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.

Thank you, it was set at 3, doh!

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?