opnsense / core

OPNsense GUI, API and systems backend
https://opnsense.org/
BSD 2-Clause "Simplified" License
3.36k stars 752 forks source link

ISC DHCPv4 need restart on vlan interface #7875

Open Franck78 opened 1 month ago

Franck78 commented 1 month ago

Important notices

Before you add a new report, we ask you kindly to acknowledge the following:

Describe the bug

DHCP server is not responding to "Request":

root@opnSense:~ # tcpdump -t -n -i em2_vlan832                                                                                                                
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode                                                                                     
listening on em2_vlan832, link-type EN10MB (Ethernet), snapshot length 262144 bytes                                                                           
IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 398                                                                    
IP6 fe80::a63e:51ff:fe78:96d6.546 > ff02::1:2.547: dhcp6 solicit                                                                                              
IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 398                                                                    
IP6 fe80::a63e:51ff:fe78:96d6.546 > ff02::1:2.547: dhcp6 solicit                                                                                              
IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 398                                                                    

To Reproduce Apparently, this is related to when opnSense retrieve the WAN interface or maybe when any interface reappears. not easy to spot the event and link it to the deconnection of ICS Dhcp server (even with a 10minutes lease time).

OpnSense interfaces:

GPon_nic (vtnet0) -> (diectly to the fiber optic gpon)
 LAN_nic (vtnet1) -> v4: 10.0.0.200/16    v6/t6: 2a01:xxxxxfe/64
 LB_nic (em2_vlan832) -> v4: 192.168.30.2/24
 WAN_nic (em0_vlan832) -> v4/DHCP4: 82.125.xxx.xxx/23  v6/DHCP6: fe80::5054:ff:fe93:6c4c%em0_vlan832/64

Relevant log files

2024-09-19T09:30:39 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-18T09:54:50 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-17T23:04:38 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-16T22:37:44 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-13T17:49:51 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-12T18:14:03 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-12T18:07:11 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-11T21:26:58 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-10T18:14:03 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-08T18:53:41 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-06T01:29:35 Error dhcpd receive_packet failed on em2_vlan832: Device not configured
2024-09-06T01:14:39 Error dhcpd receive_packet failed on em2_vlan832: Device not configured

If applicable, information from log files supporting your claim.

As soon as ICS DHCPv4 is restarted by OpnSense web interface, the livebox gets the lease and everything is ok until some hours:

tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on em2_vlan832, link-type EN10MB (Ethernet), snapshot length 262144 bytes
IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 398
ARP, Request who-has 192.168.30.10 tell 192.168.30.2, length 28
IP6 fe80::a63e:51ff:fe78:96d6.546 > ff02::1:2.547: dhcp6 solicit
IP 192.168.30.2.67 > 255.255.255.255.68: BOOTP/DHCP, Reply, length 417
IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 404
IP 192.168.30.2.67 > 255.255.255.255.68: BOOTP/DHCP, Reply, length 417
ARP, Request who-has 192.168.30.2 tell 192.168.30.10, length 46
IP 192.168.30.2 > 192.168.30.10: ICMP echo request, id 11012, seq 0, length 28
ARP, Reply 192.168.30.2 is-at 52:54:00:cd:5f:42, length 28
ARP, Request who-has 192.168.30.2 tell 192.168.30.10, length 46
ARP, Reply 192.168.30.2 is-at 52:54:00:cd:5f:42, length 28
IP 192.168.30.10 > 192.168.30.2: ICMP echo reply, id 11012, seq 0, length 28

Environment

OPNsense 24.7.4_1-amd64 FreeBSD 14.1-RELEASE-p4 OpenSSL 3.0.15

OpnSense runs as a VM on Ubuntu server.

The livebox is provided by the ISP Orange. To have the phone working (SIP) the livebox must be online. The trick is connecting the WAN interface of the livebox on a local network port. The port is attributed to a virtual bridge. Then OpnSense is presented thoses virtual interfaces .

The difference between the regular LAN interface and the Livebox interface is mainly the VLAN 832 aspect of the setup. As if when OpnSense recovers from 'some event' at low level interfaces, ICS DCHP is not 'seeing' the new em2_vlan832 interface.

This log is just when I noticed lost of internet connection and yep, the livebox was down just after this (9h30):

2024-09-19T09:31:39 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : vxlan_configure_do())        
2024-09-19T09:31:38 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : openssh_configure_do( opt1 lan))    
2024-09-19T09:31:38 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : dhcrelay_configure_map( opt1 lan inet6))  
2024-09-19T09:31:38 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map ( opt1 lan inet6)  
2024-09-19T09:31:38 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync( lan))      
2024-09-19T09:31:34 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do( lan))      
2024-09-19T09:31:34 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do( lan))      
2024-09-19T09:31:34 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())        
2024-09-19T09:31:34 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())        
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())        
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip ( lan)      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do( lan))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN_nic.        
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do( lan))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do( lan))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn ( lan)      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync( opt1))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do( opt1))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do( opt1))      
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())        
2024-09-19T09:31:33 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())        
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())        
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip ( opt1)      
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do( opt1))      
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN_nic.        
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do( opt1))      
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do( opt1))      
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn ( opt1)      
2024-09-19T09:31:31 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn_map ( opt1 lan inet6)  
2024-09-19T09:31:28 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'        
2024-09-19T09:31:27 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'opt1'        
2024-09-19T09:31:27 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure( inet6))      
2024-09-19T09:31:27 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp ( inet6)      
2024-09-19T09:31:27 Notice opnsense /usr/local/etc/rc.newwanipv6: IP renewal starting (address: fe80::5054:ff:fe93:6c4c%em0_vlan832 interface: opt1 device: em0_vlan832)    
2024-09-19T09:31:24 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : vxlan_configure_do())        
2024-09-19T09:31:23 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : openssh_configure_do( opt1 lan))    
2024-09-19T09:31:23 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map (execute task : dhcrelay_configure_map( opt1 lan inet6))  
2024-09-19T09:31:23 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip_map ( opt1 lan inet6)  
2024-09-19T09:31:23 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync( lan))      
2024-09-19T09:31:22 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do( lan))      
2024-09-19T09:31:22 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do( lan))      
2024-09-19T09:31:22 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())        
2024-09-19T09:31:22 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())        
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())        
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip ( lan)      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do( lan))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN_nic.        
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do( lan))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do( lan))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn ( lan)      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync( opt1))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do( opt1))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do( opt1))      
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())        
2024-09-19T09:31:20 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())        
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip_map (execute task : vxlan_configure_do())        
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip_map (execute task : openssh_configure_do( opt1))      
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip_map (execute task : dhcrelay_configure_map( opt1 inet))    
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip_map ( opt1 inet)    
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : wireguard_sync( opt1))      
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : webgui_configure_do( opt1))      
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : unbound_configure_do( opt1))      
2024-09-19T09:31:19 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : opendns_configure_do())        
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())        
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip ( opt1)      
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do( opt1))      
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN_nic.        
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do( opt1))      
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do( opt1))      
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn ( opt1)      
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn_map ( opt1 lan inet6)  
2024-09-19T09:31:18 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : ntpd_configure_do())        
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'        
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : dnsmasq_configure_do())        
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip ( opt1)      
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure vpn (execute task : wireguard_configure_do( opt1))      
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: Resyncing OpenVPN instances for interface WAN_nic.        
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure vpn (execute task : openvpn_configure_do( opt1))      
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure vpn (execute task : ipsec_configure_do( opt1))      
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure vpn ( opt1)      
2024-09-19T09:31:16 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure vpn_map ( opt1 inet)    
2024-09-19T09:31:15 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'opt1'        
2024-09-19T09:31:15 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure( inet6))      
2024-09-19T09:31:15 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp ( inet6)      
2024-09-19T09:31:15 Notice opnsense /usr/local/etc/rc.newwanipv6: IP renewal starting (address: fe80::5054:ff:fe93:6c4c%em0_vlan832 interface: opt1 device: em0_vlan832)    
2024-09-19T09:31:14 Notice dhcp6c dhcp6c_script: REQUEST on em0_vlan832 renewal        
2024-09-19T09:31:14 Notice dhcp6c dhcp6c_script: REQUEST on em0_vlan832 executing        
2024-09-19T09:31:12 Notice dhcp6c RTSOLD script - Sending SIGHUP to dhcp6c        
2024-09-19T09:31:11 Notice dhcp6c dhcp6c_script: REQUEST on em0_vlan832 renewal        
2024-09-19T09:31:11 Notice dhcp6c dhcp6c_script: REQUEST on em0_vlan832 executing        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure monitor (execute task : dpinger_configure_do( WAN_INTERNET_DHCP))      
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure monitor ( WAN_INTERNET_DHCP)      
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: ROUTING: keeping inet default route to 82.125.202.1        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: ROUTING: configuring inet default gateway on opt1        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.all: plugins_configure monitor (execute task : dpinger_configure_do(1))        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.all: plugins_configure monitor (1)        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.all: ROUTING: setting inet default route to 82.125.202.1        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.all: ROUTING: configuring inet default gateway on opt1        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: ROUTING: entering configure using 'opt1'        
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.newwanip: IP renewal starting (new: 82.125.202.129 old: 82.125.202.129 interface: opt1 device: em0_vlan832 force: yes)
2024-09-19T09:31:10 Notice opnsense /usr/local/etc/rc.all: ROUTING: entering configure using defaults        
2024-09-19T09:31:10 Notice dhcp6c RTSOLD script - Sending SIGHUP to dhcp6c        
2024-09-19T09:31:09 Notice dhclient dhclient-script: Creating resolv.conf        
2024-09-19T09:31:09 Notice dhclient dhclient-script: New Routers (em0_vlan832): 82.125.202.1        
2024-09-19T09:31:09 Notice dhclient dhclient-script: New Broadcast Address (em0_vlan832): 82.125.203.255        
2024-09-19T09:31:09 Notice dhclient dhclient-script: New Subnet Mask (em0_vlan832): 255.255.254.0        
2024-09-19T09:31:09 Notice dhclient dhclient-script: New IP Address (em0_vlan832): 82.125.202.129        
2024-09-19T09:31:09 Notice dhclient dhclient-script: New Hostname (em0_vlan832): opnSense        
2024-09-19T09:31:09 Notice dhclient dhclient-script: Reason BOUND on em0_vlan832 executing        
2024-09-19T09:31:09 Error dhclient unknown dhcp option value 0x7d        
2024-09-19T09:31:09 Error dhclient unknown dhcp option value 0x5a        
2024-09-19T09:31:09 Notice dhclient dhclient-script: Reason ARPCHECK on em0_vlan832 executing        
2024-09-19T09:31:07 Notice dhclient dhclient-script: Reason ARPSEND on em0_vlan832 executing        
2024-09-19T09:31:07 Error dhclient unknown dhcp option value 0x7d        
2024-09-19T09:31:07 Error dhclient unknown dhcp option value 0x5a        
2024-09-19T09:30:40 Notice dhclient dhclient-script: Reason PREINIT on em0_vlan832 executing        
2024-09-19T09:30:40 Error dhclient ^        
2024-09-19T09:30:40 Error dhclient   vlan-id      
2024-09-19T09:30:40 Error dhclient /var/etc/dhclient_opt1.conf line 13: expecting a statement.        
2024-09-19T09:30:40 Error dhclient ^        
2024-09-19T09:30:40 Error dhclient   vlan-parent      
2024-09-19T09:30:40 Error dhclient /var/etc/dhclient_opt1.conf line 11: expecting a statement.        
2024-09-19T09:30:39 Notice kernel <6>vlan1: changing name to 'em2_vlan832'        
2024-09-19T09:30:39 Warning rtsold interface vlan1 removed        
2024-09-19T09:30:39 Notice kernel <6>vtnet2: promiscuous mode disabled        
2024-09-19T09:30:39 Notice kernel <6>vlan0: changing name to 'em0_vlan832'        
2024-09-19T09:30:39 Warning rtsold interface em2_vlan832 removed        
2024-09-19T09:30:39 Warning rtsold interface vlan0 removed        
2024-09-19T09:30:39 Warning rtsold interface em0_vlan832 removed        
2024-09-19T09:30:39 Critical dhclient exiting.        
2024-09-19T09:30:39 Error dhclient connection closed        
2024-09-19T09:30:39 Critical dhclient exiting.        
2024-09-19T09:30:39 Error dhclient No live interfaces to poll on - exiting.        
2024-09-19T09:30:39 Error dhclient Interface em0_vlan832 no longer appears valid.        
2024-09-19T09:30:39 Error dhclient ioctl(SIOCGIFFLAGS) on em0_vlan832: Operation not permitted        
2024-09-19T09:30:39 Error dhclient receive_packet failed on em0_vlan832: Device not configured        
2024-09-19T06:12:18 Notice kernel <6>em2_vlan832: promiscuous mode enabled        
2024-09-19T06:12:18 Notice kernel <6>vtnet2: promiscuous mode enabled        
Franck78 commented 1 month ago

Cut this morning (11h57).

Wan interface em0_vlan832 was briefly lost causing the 'newwanip' thing to activate.

This time I clearly saw the em2_vlan832 (livebox) disconnected :

2024-09-20T11:57:55 Error dhclient unknown dhcp option value 0x7d  
2024-09-20T11:57:55 Error dhclient unknown dhcp option value 0x5a  
2024-09-20T11:57:54 Notice dhclient dhclient-script: Reason ARPCHECK on em0_vlan832 executing  
2024-09-20T11:57:52 Notice dhclient dhclient-script: Reason ARPSEND on em0_vlan832 executing  
2024-09-20T11:57:52 Error dhclient unknown dhcp option value 0x7d  
2024-09-20T11:57:52 Error dhclient unknown dhcp option value 0x5a  
2024-09-20T11:57:37 Notice dhclient dhclient-script: Reason PREINIT on em0_vlan832 executing  
2024-09-20T11:57:37 Error dhclient ^  
2024-09-20T11:57:37 Error dhclient   vlan-id
2024-09-20T11:57:37 Error dhclient /var/etc/dhclient_opt1.conf line 13: expecting a statement.  
2024-09-20T11:57:37 Error dhclient ^  
2024-09-20T11:57:37 Error dhclient   vlan-parent
2024-09-20T11:57:37 Error dhclient /var/etc/dhclient_opt1.conf line 11: expecting a statement.  
2024-09-20T11:57:37 Notice kernel <6>vlan1: changing name to 'em2_vlan832'  
2024-09-20T11:57:37 Notice kernel <6>vtnet2: promiscuous mode disabled  
2024-09-20T11:57:36 Warning rtsold interface vlan1 removed  
2024-09-20T11:57:36 Warning rtsold interface em2_vlan832 removed  
2024-09-20T11:57:36 Notice kernel <6>vlan0: changing name to 'em0_vlan832'  
2024-09-20T11:57:36 Warning rtsold interface vlan0 removed  
2024-09-20T11:57:36 Warning rtsold interface em0_vlan832 removed  
2024-09-20T11:57:36 Critical dhclient exiting.  
2024-09-20T11:57:36 Error dhclient connection closed  
2024-09-20T11:57:36 Critical dhclient exiting.  
2024-09-20T11:57:36 Error dhclient No live interfaces to poll on - exiting.  
2024-09-20T11:57:36 Error dhclient Interface em0_vlan832 no longer appears valid.  
2024-09-20T11:57:36 Error dhclient ioctl(SIOCGIFFLAGS) on em0_vlan832: Operation not permitted  
2024-09-20T11:57:36 Error dhclient receive_packet failed on em0_vlan832: Device not configured  

(tcpdump started early) 2024-09-20T08:37:27 | Notice | kernel | <6>em2_vlan832: promiscuous mode enabled |  

The problem started at 11h56, the livebox receive no answsers. Then at 11:56:26, the interface disappeared.

11:55:43.883182 IP 192.168.30.10.68 > 192.168.30.2.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 392
11:55:43.898044 IP 192.168.30.2.67 > 192.168.30.10.68: BOOTP/DHCP, Reply, length 417
11:55:49.850427 ARP, Request who-has 192.168.30.2 tell 192.168.30.10, length 46
11:55:49.850455 ARP, Reply 192.168.30.2 is-at 52:54:00:cd:5f:42, length 28
11:56:01.195833 IP6 fe80::a63e:51ff:fe78:96d6.546 > ff02::1:2.547: dhcp6 solicit
11:56:05.531394 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:06.532677 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:07.533941 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:08.535733 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:09.536008 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:10.538910 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:11.539980 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:12.542119 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:23.651065 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:24.652450 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:25.655207 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:26.656810 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:31.662599 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:32.664134 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:33.668751 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:34.670232 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:47.675791 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:48.677327 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:49.679138 IP 192.168.30.10.42250 > 80.10.246.136.53: 55989+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:56:50.679676 IP 192.168.30.10.36973 > 81.253.149.6.53: 24435+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:57:11.552660 IP 192.168.30.10.43666 > 80.10.246.136.53: 48034+ A? audiphone-lb4-fr.odmtrack.orange.com. (54)
11:57:11.552805 IP 192.168.30.10.53183 > 80.10.246.136.53: 49808+ AAAA? audiphone-lb4-fr.odmtrack.orange.com. (54)
11:57:16.561011 IP 192.168.30.10.43666 > 81.253.149.6.53: 48034+ A? audiphone-lb4-fr.odmtrack.orange.com. (54)
11:57:16.561157 IP 192.168.30.10.53183 > 81.253.149.6.53: 49808+ AAAA? audiphone-lb4-fr.odmtrack.orange.com. (54)
11:57:19.689983 IP 192.168.30.10.39822 > 80.10.246.136.53: 14340+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:57:20.691570 IP 192.168.30.10.44640 > 81.253.149.6.53: 20472+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:57:21.568506 IP 192.168.30.10.39211 > 80.10.246.136.53: 46544+ A? audiphone-lb4-fr.odmtrack.orange.com.VEL.access.orange-multimedia.net. (87)
11:57:21.568650 IP 192.168.30.10.41755 > 80.10.246.136.53: 41337+ AAAA? audiphone-lb4-fr.odmtrack.orange.com.VEL.access.orange-multimedia.net. (87)
11:57:21.693923 IP 192.168.30.10.39822 > 80.10.246.136.53: 14340+ AAAA? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:57:22.695914 IP 192.168.30.10.44640 > 81.253.149.6.53: 20472+ A? epdg.epc.mnc001.mcc208.pub.3gppnetwork.org. (60)
11:57:26.574665 IP 192.168.30.10.39211 > 80.10.246.136.53: 46544+ A? audiphone-lb4-fr.odmtrack.orange.com.VEL.access.orange-multimedia.net. (87)
11:57:26.574757 IP 192.168.30.10.41755 > 80.10.246.136.53: 41337+ AAAA? audiphone-lb4-fr.odmtrack.orange.com.VEL.access.orange-multimedia.net. (87)
tcpdump: pcap_loop: The interface disappeared

From now, the ICSDHCPv4 will never honor em2_vlan832 until restart of dhcp service.

root@opnSense:~ # tcpdump -n -i em2_vlan832
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on em2_vlan832, link-type EN10MB (Ethernet), snapshot length 262144 bytes
12:37:26.208689 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from a4:3e:51:78:96:d6, length 398
12:37:56.550380 IP6 fe80::a63e:51ff:fe78:96d6.546 > ff02::1:2.547: dhcp6 solicit

nothing particular at line 11 & 13, dhclient 'error' in the log

root@opnSense:~ # cat /var/etc/dhclient_opt1.conf 
interface "em0_vlan832" {
        # DHCP Protocol Timing Values
        timeout 8;
        retry 3;

        # DHCP Protocol Options
        send dhcp-class-identifier "sagem";
        send user-class "+FSVDSL_livebox.Internet.softathome.Livebox4";
        send option-90    f3:3b:ac:b9:a5;
        request subnet-mask, routers, domain-name-servers,  broadcast-address,   dhcp-lease-time,  dhcp-renewal-time, dhcp-rebinding-time,  domain-search, option-90, option-120, option-125;
        vlan-parent "em0";
        vlan-pcp 6;
        vlan-id 832;

        script "/usr/local/opnsense/scripts/interfaces/dhclient-script";
        supersede interface-mtu 0;
}
root@opnSense:~ # ls -l  /var/etc/dhclient_opt1.conf
-rw-r--r--  1 root wheel 761 Sep 20 11:57 /var/etc/dhclient_opt1.conf
fichtner commented 1 month ago

Hmm some of the custom options in dhclient are no longer supported. Is this an old box that was just recently upgraded?

Franck78 commented 1 month ago

Hi fichtner

The physical Livebox is not so old but is not the problem. If you want the geographic phone number, the livebox is mandatory because Orange doesn't share its SIP specification.

So, opnSense simulates correctly a 'virtual' Livebox to connect on em0_vlan832 to Orange. Maybe some Orange modified the 'protocol' for allowing a livebox to connect, ok. But until opnSense stops connecting as a livebox, no need to search anything here for now.

When Orange will block voluntarily or not opnSense, this topic (in french) will wake up: https://lafibre.info/remplacer-livebox/cacking-nouveau-systeme-de-generation-de-loption-90-dhcp/456/

For me, I'm quite sure I found the cause of my problem. Can you check that the newwanip thing also restarts dhcpserver on VLAN interfaces ? em2_vlan832 is invisible to the dhcp server !

Another topic on LiveBox/opnSense, just for info: https://wiki.opnsense.org/manual/how-tos/orange_fr_fttp.html https://lafibre.info/remplacer-livebox/opnsense-remplacer-livebox-aucune-modification-necessaire/1140/

fichtner commented 1 month ago

@Franck78 the answer to your question is simple: DHCP doesn't restart for the simple fact that it binds to all interfaces at the same time anyway. Couple the fact that VLANs are online before DHCP even starts and never changed thereafter (unless manually modified) the situation you run into is rather strange.

What I do refer to regarding Orange is the fact that vlan-parent, vlan-pcp and vlan-id are obsolete and you only have to use the 'Use VLAN priority' setting with value 'Internetwork Control (6)' now.

https://github.com/opnsense/docs/commit/cc565a2ca5d

Franck78 commented 1 month ago

ok, I know why your are confused. I forgot an important piece of info.

I started with 19.1.7 and Orange livebox, ok zero problem on Ubuntu server 2018 At some point I upgraded to Ubuntu 2020 and to opnSense 20.7

Since then, the Wan (FFTH) became unreliable. Add to do numerous manual reboot.

Then I installed monit to detect the bad condition, no exchange on the wan link. The action of monit was lauch "/usr/local/etc/rc.reload_all"

I also made a short version to minimize the reload:

/* core service reload */
system_resolver_configure(true);
interfaces_configure(true);
system_routing_configure(true);
filter_configure_sync(true);

All this was more or less OK until opnSense 24.7 With 24.7 and this monit fix, restarting the DHCP server is mandatory.

But now

My 'new' expectation is that opnSense reconnects alone to Orange. This new config changes everything.

I need some days to see what is happening now.

fichtner commented 1 month ago

My guess is the behaviour differs from FreeBSD 13.2 to 14.1. I can see that interfaces_configure() would be rather disruptive in general which is why you only find this in rc.bootup and rc.reload_all which also both start DHCP. I would simply suggest to add the necessary function to do that.

Cheers, Franco

Franck78 commented 1 month ago

The change of the mode of connection between opnSense and Orange (eg livebox v6) made it very stable. No disconnection. That's a good news. With the old way, opnSense was unable to restore itself the WAN. My "solution" was detecting the loss, after 3 minutes, launch a partial 'rc.restartall' Maybe that 'rc.restartll' was messing (is) with DHCPv4 preventing it from responding to the em2_vlan832.

I will close this if I don't see loss of the real livebox behind her em2_vlan832 ;) One month.

thank you