Hotplug event causes rc.start_packages: Restarting/Starting all packages
-
It seems unexpected but I probably call it a missing feature. Most installs don't see an interface go up/down except in a significant network event and it's safer for those to restart packages than to leave then potentially running with the wrong IP.
However running rc.newwanip on something that isn't a WAN seems unnecessary and I don't see that here. For example connecting to LAN on a 4100 in 22.05:Sep 16 00:32:08 check_reload_status 495 Linkup starting igc0 Sep 16 00:32:08 kernel igc0: link state changed to UP Sep 16 00:32:09 php-fpm 38757 /rc.linkup: DEVD Ethernet attached event for lan Sep 16 00:32:09 php-fpm 38757 /rc.linkup: HOTPLUG: Configuring interface lan Sep 16 00:32:10 php-fpm 38757 /rc.linkup: Gateway, NONE AVAILABLE Sep 16 00:32:10 check_reload_status 495 Restarting IPsec tunnels Sep 16 00:32:14 check_reload_status 495 updating dyndns lan Sep 16 00:32:14 check_reload_status 495 Reloading filter
Something is different about my config there though since it doesn't list the static IP even though it is configured with one. It really looks like your config has caused pfSense to think opt4 is a WAN.
Are you able to upload that for review? Or replicate it in a very basic config that you can share?Steve
-
Is there a way I can direct message you a link to download my config from my cloud provider?
Also, would it break the config if I pulled out my workstation information and it would also have my wireguard config in plain text. I guess, which backup areas would you need to take a look at?
-
You can upload something to me here:
https://nc.netgate.com/nextcloud/s/yPwaeQLsdK5rK9r
You can remove any details you need to.If you're able to upload the status_output diagnostic file that already has passwords and cert keys etc redacted:
https://docs.netgate.com/pfsense/en/latest/recipes/diagnostic-data.html#copying-the-diagnostic-data-archiveSteve
-
Files have been uploaded. Let me know if you need anything else. Thank you for your help!
-
Hmm, there's really nothing significantly different in your config there. At least not currently.
Are you able to reproduce the issue and then upload a new status file? I don't see any connections to em5 in the logs in the last few days.
Steve
-
Yes, however, it’s my work laptop so I won’t be able to do it at the moment. I will test it out after work and upload a new file for your review.
Currently, I have em5 attached to a switch so it doesn’t restart packages so that’s why you’re not seeing any information - I think.
-
Ah, yes, that would do it. Ok, let me know you're able to test it again.
Steve
-
I uploaded a new status_output.tgz file for your review.
Off Topic
On something completely unrelated, was something recently updated and pushed out? The following occurred today:Sep 16 18:53:37 pkg-static 86631 pfSense-repo upgraded: 22.05_2 -> 22.05_5 Sep 16 18:53:37 pkg-static 86631 pfSense-upgrade upgraded: 1.0_26 -> 1.0_27
Now, I am unable to check for any packages and it thinks I do not have any packages installed when I do.
pkg-static -d update
DBG(1)[69590]> pkg initialized pkg-static: invalid url: /pfSense_plus-v22_05_amd64-core pkg-static: Cannot parse configuration file!
-
@32g3liqxu8 I saw that error/issue also this afternoon.
-
Yup just hit it and found the cause. Working on it now...
-
Thank you!
-
The repo issue is still being worked on.
The package restart issue is odd. Seems like there's a logic error there. I managed to replicate it on a different interface and the only difference is that it doesn't have 'track-interface' set for IPv6.
You don't appear to have any v6 connectivity there so to test it you would need to enable dhcpv6 on something in order to set opt4 to track it. If you can test that and confirm that prevents rc.newwanip running then we'll need to dig into that deeper.
Steve
-
I turned on v6 connectivity on my WAN interface. I set OPT4 to track the interface gateway of WAN_DHCP6. I powered on my laptop, and I am not seeing the rc.newwanip for em5, but it does occur for WAN_DHCP6, and that's likely because the WAN_DHCP6 is offline. I'm not sure I set that part up correctly. I'm not very familiar with IPv6. Let me know if this is not a good enough test
Sep 17 12:35:36 pfSense check_reload_status[401]: Linkup starting em5 Sep 17 12:35:36 pfSense kernel: em5: link state changed to DOWN Sep 17 12:35:37 pfSense php-fpm[42065]: /rc.linkup: DEVD Ethernet detached event for opt4 Sep 17 12:35:37 pfSense check_reload_status[401]: Reloading filter Sep 17 12:35:38 pfSense check_reload_status[401]: Linkup starting em5 Sep 17 12:35:38 pfSense kernel: em5: link state changed to UP Sep 17 12:35:38 pfSense php-fpm[42065]: /rc.filter_configure_sync: GW States: One or more gateways is down, flushing all states: WAN_DHCP6 Sep 17 12:35:39 pfSense php-fpm[371]: /rc.linkup: DEVD Ethernet attached event for opt4 Sep 17 12:35:39 pfSense php-fpm[371]: /rc.linkup: HOTPLUG: Configuring interface opt4 Sep 17 12:35:39 pfSense php-fpm[371]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. 'WAN_DHCP6' Sep 17 12:35:39 pfSense check_reload_status[401]: Restarting IPsec tunnels Sep 17 12:35:40 pfSense php-fpm[69043]: /rc.newwanipv6: rc.newwanipv6: Info: starting on em0. Sep 17 12:35:40 pfSense php-fpm[69043]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2603:900a:ff00:1b:596b:b440:d2fb:e381) (interface: wan) (real interface: em0). Sep 17 12:35:41 pfSense nginx: 2022/09/17 12:35:41 [crit] 71665#100551: *7384 SSL_write() failed (13: Permission denied) while processing HTTP/2 connection, client: 192.168.1.51, server: 0.0.0.0:443 Sep 17 12:35:42 pfSense php-fpm[371]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1663432542] unbound[69211:0] error: bind: address already in use [1663432542] unbound[69211:0] fatal error: could not open ports' Sep 17 12:35:44 pfSense rc.gateway_alarm[18167]: >>> Gateway alarm: WAN_DHCP6 (Addr:fe80::2bc:60ff:fe93:419%em0 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Sep 17 12:35:44 pfSense check_reload_status[401]: updating dyndns WAN_DHCP6 Sep 17 12:35:44 pfSense check_reload_status[401]: Restarting IPsec tunnels Sep 17 12:35:44 pfSense check_reload_status[401]: Restarting OpenVPN tunnels/interfaces Sep 17 12:35:44 pfSense check_reload_status[401]: Reloading filter Sep 17 12:35:44 pfSense php-fpm[69043]: /rc.newwanipv6: Gateway, none 'available' for inet6, use the first one configured. 'WAN_DHCP6' Sep 17 12:35:44 pfSense check_reload_status[401]: Reloading filter Sep 17 12:35:45 pfSense check_reload_status[401]: updating dyndns opt4 Sep 17 12:35:46 pfSense php-fpm[69043]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. 'WAN_DHCP6' Sep 17 12:35:46 pfSense php-fpm[42065]: /rc.filter_configure_sync: GW States: One or more gateways is down, flushing all states: WAN_DHCP6 Sep 17 12:35:47 pfSense php-fpm[39466]: /rc.filter_configure_sync: GW States: One or more gateways is down, flushing all states: WAN_DHCP6 Sep 17 12:36:00 pfSense sshguard[43717]: Exiting on signal.
-
I there a redmine issue for this bug? I'd like to follow it and if there is a patch, apply it on one of my systems. Thanks.
-
Not yet.It's not clear which way the intended behaviour is but I'm pretty sure it should be the same for a link-up/down event regardless of whether it's tracking something else for v6.
What behaviour are you seeing?Steve
-
Thanks. I'm seeing behavior to that reported here. On a NetGate 6100 Max running pfSense 22.05-Release without ipv6. Whenever I connect to a LAN port, it runs rc.renewwanip and in some cases, whatever else it does affects other LAN segments connected to NICs on the 6100.
Given that the issue manifests when ipv6 is disabled, from your analysis, do you know the minimum ipv6 config that I would need to work around the issue?
-
When I was testing it did not do it on an interface set to track WAN for v6. So I would try setting WAN to DHCPv6 (even if no DHCPv6 server exists) and setting LAN to track that. That's the default config which is why I suspect it's not seen by more people.
Steve
-
@stephenw10 I ran a couple tests and confirmed that enabling ipv6 tracking on the hot-plug interface works around the problem so it seems like a logic bug.
Without ipv6 tracking (WAN DHCP6, ADMIN none)
Nov 9 16:52:40 firewall kernel: ix3: link state changed to DOWN Nov 9 16:52:41 firewall php-fpm[384]: /rc.linkup: Hotplug event detected for ADMIN(opt1) static IP (172.16.50.200 ) Nov 9 16:52:41 firewall check_reload_status[422]: Reloading filter Nov 9 16:52:44 firewall check_reload_status[422]: Linkup starting ix3 Nov 9 16:52:44 firewall kernel: ix3: link state changed to UP Nov 9 16:52:45 firewall php-fpm[383]: /rc.linkup: Hotplug event detected for ADMIN(opt1) static IP (172.16.50.200 ) Nov 9 16:52:45 firewall check_reload_status[422]: rc.newwanip starting ix3 Nov 9 16:52:45 firewall check_reload_status[422]: Reloading filter Nov 9 16:52:46 firewall php-fpm[383]: /rc.newwanip: rc.newwanip: Info: starting on ix3. Nov 9 16:52:46 firewall php-fpm[383]: /rc.newwanip: rc.newwanip: on (IP address: 172.16.50.200) (interface: ADMIN[opt1]) (real interface: ix3). Nov 9 16:52:47 firewall php-fpm[383]: /rc.newwanip: Gateway, NONE AVAILABLE Nov 9 16:52:47 firewall php-fpm[383]: /rc.newwanip: Gateway, NONE AVAILABLE Nov 9 16:52:49 firewall dhcpleases[52345]: Could not deliver signal HUP to process 65492: No such process. Nov 9 16:52:52 firewall php-fpm[383]: /rc.newwanip: Resyncing OpenVPN instances for interface ADMIN. Nov 9 16:52:52 firewall php-fpm[383]: /rc.newwanip: Creating rrd update script Nov 9 16:52:54 firewall php-fpm[383]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 172.16.50.200 -> 172.16.50.200 - Restarting packages. Nov 9 16:52:54 firewall check_reload_status[422]: Starting packages Nov 9 16:52:55 firewall php-fpm[65895]: /rc.start_packages: Restarting/Starting all packages. Nov 9 16:52:55 firewall check_reload_status[422]: Reloading filter Nov 9 16:52:55 firewall ftp-proxy[31983]: listening on 127.0.0.1 port 8021
With ipv6 (WAN DHCP6, ADMIN track WAN)
Nov 9 16:54:59 firewall check_reload_status[422]: Linkup starting ix3 Nov 9 16:54:59 firewall kernel: ix3: link state changed to DOWN Nov 9 16:55:00 firewall php-fpm[11301]: /rc.linkup: DEVD Ethernet detached event for opt1 Nov 9 16:55:00 firewall check_reload_status[422]: Reloading filter Nov 9 16:55:02 firewall check_reload_status[422]: Linkup starting ix3 Nov 9 16:55:02 firewall kernel: ix3: link state changed to UP Nov 9 16:55:03 firewall php-fpm[6082]: /rc.linkup: DEVD Ethernet attached event for opt1 Nov 9 16:55:03 firewall php-fpm[6082]: /rc.linkup: HOTPLUG: Configuring interface opt1 Nov 9 16:55:03 firewall php-fpm[6082]: /rc.linkup: Gateway, NONE AVAILABLE Nov 9 16:55:03 firewall php-fpm[6082]: /rc.linkup: Gateway, NONE AVAILABLE Nov 9 16:55:03 firewall check_reload_status[422]: Restarting IPsec tunnels Nov 9 16:55:05 firewall dhcpleases[87360]: Could not deliver signal HUP to process 39205: No such process. Nov 9 16:55:09 firewall check_reload_status[422]: updating dyndns opt1
Do these tests make it actionable enough for a redmine issue and fix?
-
Yes, I believe so. Let me discuss it internally and get something open.
-
Hello i know that is not my threat but i think that i might have the same problem.
If i restart one of my pc (it is connected directly to pfsense) my wg tunnel will go down and only after rebooting my pfsense i am able to make it work again. Some one can give me a workaround for my Wg tunnel to come up without restarting my pfsense.
Thank you.Nov 10 14:25:35 php 50499 [pfBlockerNG] filterlog daemon started Nov 10 14:25:35 tail_pfb 50062 [pfBlockerNG] Firewall Filter Service started Nov 10 14:25:35 php_pfb 47352 [pfBlockerNG] filterlog daemon stopped Nov 10 14:25:35 tail_pfb 47026 [pfBlockerNG] Firewall Filter Service stopped Nov 10 14:25:35 lighttpd_pfb 44920 [pfBlockerNG] DNSBL Webserver started Nov 10 14:25:35 lighttpd_pfb 43815 [pfBlockerNG] DNSBL Webserver stopped Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Applied package default settings as necessary. Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Installed Unbound ACL group (WireGuard). Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed Unbound ACL group (WireGuard). Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed interface group (WireGuard). Nov 10 14:25:35 check_reload_status 411 Syncing firewall Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Installed earlyshellcmd(s). Nov 10 14:25:35 check_reload_status 411 Syncing firewall Nov 10 14:25:35 php-fpm 60035 /rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed earlyshellcmd(s). Nov 10 14:25:32 upsd 24397 Startup successful Nov 10 14:25:32 upsd 24142 Connected to UPS [APC]: usbhid-ups-APC Nov 10 14:25:32 upsd 24142 listening on 127.0.0.1 port 3493 Nov 10 14:25:32 upsd 24142 listening on ::1 port 3493 Nov 10 14:25:32 upsd 24142 listening on 192.168.2.1 port 3493 Nov 10 14:25:32 upsd 24142 listening on 192.168.4.1 port 3493 Nov 10 14:25:32 usbhid-ups 22587 Startup successful Nov 10 14:25:31 upsmon 21917 Startup successful Nov 10 14:25:31 php-fpm 60035 /rc.start_packages: Starting service nut Nov 10 14:25:31 usbhid-ups 79003 Signal 15: exiting Nov 10 14:25:31 upsd 19203 Signal 15: exiting Nov 10 14:25:31 upsd 19203 mainloop: Interrupted system call Nov 10 14:25:31 upsd 19203 User local-monitor@127.0.0.1 logged out from UPS [APC] Nov 10 14:25:31 upsmon 77054 Signal 15: exiting Nov 10 14:25:31 php-fpm 60035 /rc.start_packages: Stopping service nut Nov 10 14:25:31 check_reload_status 411 Syncing firewall Nov 10 14:25:31 php-fpm 60035 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Aliases Nov 10 14:25:31 php-fpm 60035 /rc.start_packages: Restarting/Starting all packages. Nov 10 14:25:30 check_reload_status 411 Starting packages Nov 10 14:25:30 php-fpm 60035 /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 192.168.4.1 -> 192.168.4.1 - Restarting packages. Nov 10 14:25:29 php-fpm 14803 /rc.newwanip: dpinger: timeout while retrieving status for gateway WAN_EPORTS_PPPOE Nov 10 14:25:28 php-fpm 60035 /rc.newwanip: Creating rrd update script Nov 10 14:25:28 php-fpm 60035 /rc.newwanip: Resyncing OpenVPN instances for interface DMZ. Nov 10 14:25:27 check_reload_status 411 Reloading filter Nov 10 14:25:27 check_reload_status 411 Restarting OpenVPN tunnels/interfaces Nov 10 14:25:27 check_reload_status 411 Restarting IPsec tunnels Nov 10 14:25:27 check_reload_status 411 updating dyndns WG_mamaGW Nov 10 14:25:27 rc.gateway_alarm 76312 >>> Gateway alarm: WG_mamaGW (Addr:10.1.1.1 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Nov 10 14:25:25 php-fpm 14803 /rc.newwanip: Removing static route for monitor xxx.xxx.xxx.242 and adding a new route through xxx.xxx.xxx.193 Nov 10 14:25:25 php-fpm 14803 /rc.newwanip: rc.newwanip: on (IP address: 192.168.4.1) (interface: DMZ[opt3]) (real interface: em3). Nov 10 14:25:25 php-fpm 14803 /rc.newwanip: rc.newwanip: Info: starting on em3. Nov 10 14:25:24 check_reload_status 411 Reloading filter Nov 10 14:25:24 check_reload_status 411 rc.newwanip starting em3 Nov 10 14:25:24 php-fpm 14803 /rc.linkup: Hotplug event detected for DMZ(opt3) static IP (192.168.4.1 ) Nov 10 14:25:23 kernel em3: link state changed to UP Nov 10 14:25:23 check_reload_status 411 Linkup starting em3 Nov 10 14:25:22 php-fpm 60035 /rc.newwanip: dpinger: timeout while retrieving status for gateway WAN_EPORTS_PPPOE Nov 10 14:25:21 check_reload_status 411 Reloading filter Nov 10 14:25:21 php-fpm 31658 /rc.linkup: Hotplug event detected for DMZ(opt3) static IP (192.168.4.1 ) Nov 10 14:25:21 check_reload_status 411 Reloading filter Nov 10 14:25:21 check_reload_status 411 Restarting OpenVPN tunnels/interfaces Nov 10 14:25:21 check_reload_status 411 Restarting IPsec tunnels Nov 10 14:25:21 check_reload_status 411 updating dyndns WG_mamaGW Nov 10 14:25:21 rc.gateway_alarm 56603 >>> Gateway alarm: WG_mamaGW (Addr:10.1.1.1 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Nov 10 14:25:20 kernel em3: link state changed to DOWN Nov 10 14:25:20 check_reload_status 411 Linkup starting em3 Nov 10 14:25:19 php-fpm 60035 /rc.newwanip: Removing static route for monitor xxx.xxx.xxx.242 and adding a new route through xxx.xxx.xxx.193 Nov 10 14:25:18 php-fpm 60035 /rc.newwanip: rc.newwanip: on (IP address: 192.168.4.1) (interface: DMZ[opt3]) (real interface: em3). Nov 10 14:25:18 php-fpm 60035 /rc.newwanip: rc.newwanip: Info: starting on em3. Nov 10 14:25:17 check_reload_status 411 Reloading filter Nov 10 14:25:17 check_reload_status 411 rc.newwanip starting em3 Nov 10 14:25:17 php-fpm 60035 /rc.linkup: Hotplug event detected for DMZ(opt3) static IP (192.168.4.1 ) Nov 10 14:25:16 kernel em3: link state changed to UP Nov 10 14:25:16 check_reload_status 411 Linkup starting em3 Nov 10 14:25:15 check_reload_status 411 Reloading filter Nov 10 14:25:15 php-fpm 12840 /rc.linkup: Hotplug event detected for DMZ(opt3) static IP (192.168.4.1 ) Nov 10 14:25:14 check_reload_status 411 Linkup starting em3 Nov 10 14:25:14 kernel em3: link state changed to DOWN