Hi,
I observed some unexpected behaviour in dpinger / OPNsense's handling of dpinger tonight. At least to me it is unexpected, so correct me if I am wrong.
Status:
OPNSense 23.7.5-amd64 on Zotac's ZBOX with 2x 1 GBits Realteak NICs and os-realteak-re installed. Works stable for more than 4 years. WAN on re0 (no VLAN) is directly connected to a Mikrotik router provided from the ISP, so I don't have access to it.
Event:
Due to a reboot of the mikrotik there was an IF DOWN/UP at 04:19:16 - 04:19-26 and again at 04:19:45 - 04:19:49.
Observation:
1. OPNSense detected IF events and reacted accordingly. See system.log below.
2. DPinger noticed that it failed and was restarted twice. When I checked the system this morning at 10:00 I saw that dpinger for IPv6 was down - so was the gateway as shown in OPNSense's dashboard. I triggered a start of dpinger for the IPv6 gateway on the dashboard and it started successfully. The gateway became online and IPv6 was working again.
My expectation:
I would have expected dpinger for IPv6 to resume to normal operation after the incident and not to remain in STOPPED state.
Is this really intended behaviour or do I have to adjust some options for gateway monitoring?
gateways.log for the affected time:
2023-10-04T10:01:43 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr 2a00:xxxx:xxxx:xx::1 bind_addr 2a00:xxxx:xxxx:xx::2 identifier "ISP_WAN_GWv6 "
2023-10-04T04:19:50 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr xx.xx.148.97 bind_addr xx.xx.148.98 identifier "ISP_WAN_GWv4 "
2023-10-04T04:19:50 Warning dpinger exiting on signal 15
2023-10-04T04:19:49 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:48 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:47 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:46 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:45 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:44 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:43 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:42 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:41 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:40 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:39 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:38 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:37 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:36 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:35 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:34 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:33 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:32 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-04T04:19:27 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr xx.xx.148.97 bind_addr xx.xx.148.98 identifier "ISP_WAN_GWv4 "
2023-10-04T04:19:27 Warning dpinger exiting on signal 15
2023-10-04T04:19:26 Warning dpinger exiting on signal 15
2023-10-04T04:19:26 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 55
2023-10-04T04:19:25 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:25 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:24 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:24 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:23 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:23 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:22 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:22 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:21 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:21 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:20 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:20 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:19 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:19 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:18 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:18 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T04:19:17 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-04T04:19:17 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-09-28T08:56:32 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr xx.xx.148.97 bind_addr xx.xx.148.98 identifier "ISP_WAN_GWv4 "
2023-09-28T08:56:32 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr 2a00:xxxx:xxxx:xx::1 bind_addr 2a00:xxxx:xxxx:xx::2 identifier "ISP_WAN_GWv6 "
system.log for the affected time
2023-10-04T04:20:15 Warning opnsense /usr/local/etc/rc.linkup: warning: ignoring missing default tunable request: debug.pfftpproxy
2023-10-04T04:20:14 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())
2023-10-04T04:20:14 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())
2023-10-04T04:20:14 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp ()
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,wan))
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,wan)
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (execute task : dpinger_configure_do(,ISP_WAN_GWv4))
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (,ISP_WAN_GWv4)
2023-10-04T04:19:50 Warning opnsense /usr/local/etc/rc.linkup: The required ISP_WAN_GWv6 IPv6 interface address could not be found, skipping.
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (execute task : dpinger_configure_do(,ISP_WAN_GWv6))
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (,ISP_WAN_GWv6)
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: keeping inet6 default route to 2a00:xxxx:xxxx:xx::1
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: configuring inet6 default gateway on wan
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: setting inet default route to xx.xx.148.97
2023-10-04T04:19:50 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: configuring inet default gateway on wan
2023-10-04T04:19:49 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'wan'
2023-10-04T04:19:49 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for wan(re0)
2023-10-04T04:19:49 Notice kernel <6>re0: link state changed to UP
2023-10-04T04:19:46 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for wan(re0)
2023-10-04T04:19:45 Notice kernel <6>re0: link state changed to DOWN
2023-10-04T04:19:32 Warning opnsense /usr/local/etc/rc.linkup: warning: ignoring missing default tunable request: debug.pfftpproxy
2023-10-04T04:19:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())
2023-10-04T04:19:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())
2023-10-04T04:19:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp ()
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,wan))
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,wan)
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (execute task : dpinger_configure_do(,ISP_WAN_GWv4))
2023-10-04T04:19:27 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (,ISP_WAN_GWv4)
2023-10-04T04:19:27 Warning opnsense /usr/local/etc/rc.linkup: The required ISP_WAN_GWv6 IPv6 interface address could not be found, skipping.
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (execute task : dpinger_configure_do(,ISP_WAN_GWv6))
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure monitor (,ISP_WAN_GWv6)
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: keeping inet6 default route to 2a00:xxxx:xxxx:xx::1
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: configuring inet6 default gateway on wan
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: setting inet default route to xx.xx.148.97
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: configuring inet default gateway on wan
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'wan'
2023-10-04T04:19:26 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for wan(re0)
2023-10-04T04:19:26 Notice kernel <6>re0: link state changed to UP
2023-10-04T04:19:17 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for wan(re0)
2023-10-04T04:19:16 Notice kernel <6>re0: link state changed to DOWN
Tonight the same happened again and - as yesterday - dpinger for IPv6 did not come up again. Incident happened at 2023-10-05T03:10:36.
I will try to reproduce this in an easier way and file a bug.
2023-10-05T03:11:04 Notice dpinger MONITOR: ISP_WAN_GWv4 (Addr: xx.xx.148.97 Alarm: down -> none RTT: 0.3 ms RTTd: 0.0 ms Loss: 0.0 %)
2023-10-05T03:11:03 Notice dpinger Reloaded gateway watcher configuration on SIGHUP
2023-10-05T03:11:03 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr xx.xx.148.97 bind_addr xx.xx.148.98 identifier "ISP_WAN_GWv4 "
2023-10-05T03:11:03 Notice dpinger Reloaded gateway watcher configuration on SIGHUP
2023-10-05T03:11:03 Warning dpinger exiting on signal 15
2023-10-05T03:11:02 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:11:01 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:11:00 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:59 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 50
2023-10-05T03:10:58 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:57 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:56 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:55 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:54 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:53 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:52 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:51 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:50 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:49 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:48 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:47 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 64
2023-10-05T03:10:46 Notice dpinger MONITOR: ISP_WAN_GWv4 (Addr: xx.xx.148.97 Alarm: none -> down RTT: 0.0 ms RTTd: 0.0 ms Loss: 100.0 %)
2023-10-05T03:10:42 Notice dpinger Reloaded gateway watcher configuration on SIGHUP
2023-10-05T03:10:42 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr xx.xx.148.97 bind_addr xx.xx.148.98 identifier "ISP_WAN_GWv4 "
2023-10-05T03:10:42 Notice dpinger Reloaded gateway watcher configuration on SIGHUP
2023-10-05T03:10:42 Warning dpinger exiting on signal 15
2023-10-05T03:10:42 Warning dpinger exiting on signal 15
2023-10-05T03:10:41 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 55
2023-10-05T03:10:41 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:40 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-05T03:10:40 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:39 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-05T03:10:39 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:38 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-05T03:10:38 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:37 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-05T03:10:37 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 65
2023-10-05T03:10:36 Warning dpinger ISP_WAN_GWv4 xx.xx.148.97: sendto error: 50
2023-10-05T03:10:36 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 50
2023-10-04T15:05:37 Warning dpinger ISP_WAN_GWv6 2a00:xxxx:xxxx:xx::1: sendto error: 55
2023-10-04T10:01:44 Notice dpinger MONITOR: ISP_WAN_GWv6 (Addr: 2a00:xxxx:xxxx:xx::1 Alarm: loss -> none RTT: 0.2 ms RTTd: 0.0 ms Loss: 0.0 %)
2023-10-04T10:01:43 Notice dpinger Reloaded gateway watcher configuration on SIGHUP
2023-10-04T10:01:43 Warning dpinger send_interval 1000ms loss_interval 4000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 0ms loss_alarm 0% alarm_hold 10000ms dest_addr 2a00:xxxx:xxxx:xx::1 bind_addr 2a00:xxxx:xxxx:xx::2 identifier "ISP_WAN_GWv6 "
Problem persists. Bug report here: https://github.com/opnsense/core/issues/6913
The issue was solved: we are going to disable DAD for interfaces with static IPv6 addressing. The fix will be in 23.7.7.
Cheers,
Franco
Thanks!
I just tested the backport and it should do what it promised:
https://github.com/opnsense/core/commit/3c46b33a3e
# opnsense-patch 3c46b33a3e
today I updated my version, I still have a multi wan problem, the main gateway is not activated, apply this patch
# opnsense-patch 3c46b33a3e
the problem continues
Gateways: Log File
2023-10-18T19:20:05-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:04-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:03-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:02-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:01-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:00-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:19:59-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:19:58-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
Quote from: bulmaro on October 19, 2023, 03:19:39 AM
today I updated my version, I still have a multi wan problem, the main gateway is not activated, apply this patch
# opnsense-patch 3c46b33a3e
the problem continues
Gateways: Log File
2023-10-18T19:20:05-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:04-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:03-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:02-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:01-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:20:00-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:19:59-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
2023-10-18T19:19:58-06:00 Warning dpinger WAN_DHCP 1.1.1.1: sendto error: 64
Also why are you monitoring an ANYCAST IP? The cloudflare DNS 1.1.1.1 as its an ANYCAST IP/NETWORK will be reachable always if at least one of its resolver is UP.
Wouldn't be better if you ping the GW of your ISP? Or an UNICAST BASED IP that is closer to you?
Regards,
S.
The distinct error where this bugfix comes to the rescue is:
2023-10-04T04:19:27 Warning opnsense /usr/local/etc/rc.linkup: The required ISP_WAN_GWv6 IPv6 interface address could not be found, skipping.
It wasn't meant to fix anything else.
Cheers,
Franco