22.1.2 WAN ipv4 dhclient does not function after an ISP outage

[tommiy]

HI, first time poster. Recently due to weather events m ISP has had a number of outages. After each OPNSense WAN IPv4 interface does not attempt to obtain a new address. The only recovery I have tried is a complete reboot which generally makes the IPv4 WAN interface recover and get an address from ISP DHCP Server. Hoping some one can assist as its painful to have to manually deal with this each time. I'm no OPNSense expert but I think the relevant part of the logs from last night is below. Service was working until ISP went off the air. At 4.08 I unplugged the LAN interface to see if my PC could get an address, which it could.

This never used to occur and only started with the last 2 updates.

Any assistance appreciated.

Code: [Select]

2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: ROUTING: IPv6 default gateway set to wan
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'wan'
2022-03-15T04:08:04 Notice dhcp6c RTSOLD script - Sending SIGHUP to dhcp6c
2022-03-15T04:08:04 Error dhcp6c transmit failed: Network is down
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: Accept router advertisements on interface igb0
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: Clearing states for stale wan route on igb0
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: The command '/sbin/dhclient -c '/var/etc/dhclient_wan.conf' -p '/var/run/dhclient.igb0.pid' 'igb0'' returned exit code '15', the output was 'DHCPREQUEST on igb0 to 255.255.255.255 port 67 DHCPACK from xxx.xxx.xxx.1'
2022-03-15T04:08:04 Notice opnsense plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6,Array))
2022-03-15T04:08:04 Notice opnsense plugins_configure dhcp (,inet6,Array)
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for dynamic wan(igb0)
2022-03-15T00:52:44 Error configctl error in configd communication Traceback (most recent call last): File "/usr/local/opnsense/service/configd_ctl.py", line 68, in exec_config_cmd line = sock.recv(65536).decode() socket.timeout: timed out
2022-03-15T00:50:47 Notice opnsense plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2022-03-15T00:50:47 Notice opnsense plugins_configure newwanip (execute task : vxlan_configure_interface())
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (execute task : unbound_configure_do(,wan))
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (execute task : openssh_configure_do(,wan))
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (execute task : opendns_configure_do())
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (execute task : ntpd_configure_do())
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (execute task : dyndns_configure_do(,wan))
2022-03-15T00:50:45 Notice opnsense plugins_configure newwanip (,wan)
2022-03-15T00:50:45 Notice opnsense plugins_configure vpn (execute task : openvpn_configure_do(,wan))



[tommiy]

Just noticed the following in the general log as well. So appears that there is some thing wrong with unbound?

Code: [Select]

2022-03-15T04:12:41 Error configd.py [8d6eb68d-e7b4-4945-88e2-feeb42f374c1] Script action failed with Command 'pkg rquery "%n|||%v|||%c|||%sh|||0|||0|||%L|||%R|||%o" ' returned non-zero exit status 3. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 478, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.8/subprocess.py", line 364, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command 'pkg rquery "%n|||%v|||%c|||%sh|||0|||0|||%L|||%R|||%o" ' returned non-zero exit status 3.
2022-03-15T04:12:21 Error configd.py Timeout (120) executing : firmware remote
2022-03-15T04:10:22 Error configd.py Timeout (120) executing : unbound cache dump
2022-03-15T00:52:46 Error configd.py Timeout (120) executing : unbound cache dump


[franco]

Hi,

Are you using Intrusion detection in IPS mode?


Cheers,
Franco

[tommiy]

Thanks for the reply. No I do not have IDS/IPS enabled at present while trying to address this.

[tommiy]

The complete log to where opnsense seems to have died at 00:52:44 with the configd error. The 4.08am next entry is myself removing the WAN connection to OPNSense to see if a standard PC can get DHCP.

I've not more to go on except to start looking at source code by the looks. Not many replies so I guess I am by myself.

Code: [Select]

2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: Accept router advertisements on interface igb0
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: Clearing states for stale wan route on igb0
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: The command '/sbin/dhclient -c '/var/etc/dhclient_wan.conf' -p '/var/run/dhclient.igb0.pid' 'igb0'' returned exit code '15', the output was 'DHCPREQUEST on igb0 to 255.255.255.255 port 67 DHCPACK from 202.63.66.1'
2022-03-15T04:08:04 Error opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for dynamic wan(igb0)
2022-03-15T00:52:44 Error configctl error in configd communication  Traceback (most recent call last):   File "/usr/local/opnsense/service/configd_ctl.py", line 68, in exec_config_cmd     line = sock.recv(65536).decode() socket.timeout: timed out
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: The WAN_DHCP monitor address is empty, skipping.
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: The WAN_DHCP6 monitor address is empty, skipping.
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: skipping IPv6 default route
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: IPv6 default gateway set to wan
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: IPv4 default gateway set to wan
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: entering configure using 'wan'
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: On (IP address: xxx.xxx.xxx.215) (interface: WAN[wan]) (real interface: igb0).
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'igb0'
2022-03-15T00:50:44 Error opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for dynamic wan(igb0)
2022-03-15T00:50:43 Error opnsense /usr/local/etc/rc.linkup: Clearing states for stale wan route on igb0
2022-03-15T00:50:43 Error dhclient connection closed
2022-03-15T00:50:42 Error opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for dynamic wan(igb0)
2022-03-15T00:50:42 Error opnsense /usr/local/etc/rc.newwanipv6: warning: ignoring missing default tunable request: debug.pfftpproxy
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: The WAN_DHCP monitor address is empty, skipping.
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: The WAN_DHCP6 monitor address is empty, skipping.
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: keeping current default gateway 'fe80::d677:98ff:fe87:9081%igb0'
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::d677:98ff:fe87:9081
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: IPv6 default gateway set to wan
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: IPv4 default gateway set to wan
2022-03-15T00:50:40 Error opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
2022-03-15T00:50:39 Error opnsense /usr/local/etc/rc.newwanipv6: On (IP address: 2401:d002:5000:200:1::14) (interface: WAN[wan]) (real interface: igb0).
2022-03-15T00:50:39 Error opnsense /usr/local/etc/rc.newwanipv6: IPv6 renewal is starting on 'igb0'
2022-03-15T00:50:37 Error opnsense /usr/local/etc/rc.linkup: warning: ignoring missing default tunable request: debug.pfftpproxy
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: Warning! dhcpd_radvd_configure(manual) found no suitable IPv6 address on igb1
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: skipping IPv6 default route
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: IPv6 default gateway set to wan
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: IPv4 default gateway set to wan
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'wan'
2022-03-15T00:50:36 Error opnsense /usr/local/etc/rc.linkup: Accept router advertisements on interface igb0
2022-03-15T00:50:31 Error opnsense /usr/local/etc/rc.newwanip: warning: ignoring missing default tunable request: debug.pfftpproxy
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: The WAN_DHCP monitor address is empty, skipping.
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: The WAN_DHCP6 monitor address is empty, skipping.
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: skipping IPv6 default route
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: IPv6 default gateway set to wan
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: IPv4 default gateway set to wan
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: ROUTING: entering configure using 'wan'
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: On (IP address: xxx.xxx.xxx.215) (interface: WAN[wan]) (real interface: igb0).
2022-03-15T00:50:30 Error opnsense /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'igb0'
2022-03-15T00:49:09 Error dhclient send_packet: Network is down
2022-03-15T00:49:03 Error dhclient send_packet: Network is down
2022-03-15T00:49:01 Error dhclient send_packet: Network is down
2022-03-15T00:49:00 Error dhclient send_packet: Network is down



[tommiy]

The other item I have noticed is that after the restoration of service my WAN IP address is now in a different subnet. So I'm guessing some thing with OPNSense and stale or retention of trying to connect to the old address. ie. OPNSense has died trying to connect to the old address and retain that instead of requesting a new address. Just a guess.

[tommiy]

sadly no suggestions as to why this occurs in opnsense. I guess its up to myself to set up an environment, simulate and then change code.