After Cable modem power down WAN Interface gets no ip



  • Hello,
    I had to change the cable modem of my provider and have now the following problem with the new one. If the cable modem is powered off and on again pfsense does not recover. This is how it looks like:
    11318376-ae6c-4000-bb01-2a21880eac1c-Pasted Graphic.png
    I'm using the latest version (2.4.4-RELEASE-p3 (amd64) on a Intel Atom Box (Lanner FW-7525A)
    The easiest way to bring it up again is to click on release lease and renew again.
    Any idea how to make this work without manual intervention? Or is there any process who can detect WAN Status and trigger interface down uo?
    Below is the system log where I only reduced the "arpresolve: can't allocate llinfo for 84.112.46.1 on igb0" messages
    Thanks
    Ognian

    Jul 17 13:27:05 php-fpm 336 /rc.start_packages: Restarting/Starting all packages.
    Jul 17 13:27:04 check_reload_status Starting packages
    Jul 17 13:27:04 php-fpm 335 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 84.112.46.163 -> 84.112.46.163 - Restarting packages.
    Jul 17 13:27:01 php-fpm 335 /rc.newwanip: Creating rrd update script
    Jul 17 13:27:01 php-fpm 335 /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    Jul 17 13:27:01 php-fpm 335 /rc.newwanip: Ignoring IPsec reload since there are no tunnels on interface wan
    Jul 17 13:26:59 dhcpleases kqueue error: unknown
    Jul 17 13:26:59 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    Jul 17 13:26:59 dhcpleases /etc/hosts changed size from original!
    Jul 17 13:26:57 php-fpm 335 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. ''
    Jul 17 13:26:57 php-fpm 335 /rc.newwanip: Gateway, NONE AVAILABLE
    Jul 17 13:26:55 dhcpleases /etc/hosts changed size from original!
    Jul 17 13:26:55 php-fpm 335 /rc.newwanip: rc.newwanip: on (IP address: 84.112.46.163) (interface: WAN[wan]) (real interface: igb0).
    Jul 17 13:26:55 php-fpm 335 /rc.newwanip: rc.newwanip: Info: starting on igb0.
    Jul 17 13:26:54 check_reload_status rc.newwanip starting igb0
    Jul 17 13:26:44 php-fpm 54733 /status_interfaces.php: Shutting down Router Advertisment daemon cleanly
    Jul 17 13:25:38 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:40 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:39 php-fpm 336 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection . Omitting from configuration file.
    Jul 17 13:21:39 check_reload_status Reloading filter
    Jul 17 13:21:39 php-fpm 336 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jul 17 13:21:38 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:31 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:28 check_reload_status Reloading filter
    Jul 17 13:21:28 check_reload_status updating dyndns wan
    Jul 17 13:21:28 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:27 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:26 dhcpleases kqueue error: unknown
    Jul 17 13:21:25 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    Jul 17 13:21:25 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:25 dhcpleases /etc/hosts changed size from original!
    Jul 17 13:21:24 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:23 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:21:23 check_reload_status Restarting ipsec tunnels
    Jul 17 13:21:23 php-fpm 15384 /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. ''
    Jul 17 13:21:23 php-fpm 15384 /rc.linkup: Gateway, NONE AVAILABLE
    Jul 17 13:21:20 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:20:07 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:20:04 php-fpm 15384 /rc.linkup: HOTPLUG: Configuring interface wan
    Jul 17 13:20:04 php-fpm 15384 /rc.linkup: DEVD Ethernet attached event for wan
    Jul 17 13:20:04 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:20:03 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:20:03 kernel igb0: link state changed to UP
    Jul 17 13:20:03 check_reload_status Linkup starting igb0
    Jul 17 13:20:01 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:16 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:16 php-fpm 15384 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection . Omitting from configuration file.
    Jul 17 13:19:16 check_reload_status Reloading filter
    Jul 17 13:19:16 php-fpm 15384 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jul 17 13:19:15 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:01 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:01 php-fpm 54733 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. ''
    Jul 17 13:19:01 php-fpm 54733 /rc.openvpn: Gateway, NONE AVAILABLE
    Jul 17 13:19:01 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:00 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:19:00 check_reload_status Reloading filter
    Jul 17 13:19:00 check_reload_status Restarting OpenVPN tunnels/interfaces
    Jul 17 13:19:00 check_reload_status Restarting ipsec tunnels
    Jul 17 13:19:00 check_reload_status updating dyndns WAN_DHCP
    Jul 17 13:19:00 rc.gateway_alarm 64072 >>> Gateway alarm: WAN_DHCP (Addr:84.112.46.1 Alarm:1 RTT:6.903ms RTTsd:1.805ms Loss:22%)
    Jul 17 13:19:00 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:18:48 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:18:48 check_reload_status Reloading filter
    Jul 17 13:18:48 php-fpm 54733 /rc.linkup: Shutting down Router Advertisment daemon cleanly
    Jul 17 13:18:48 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:18:47 kernel arpresolve: can't allocate llinfo for 84.112.46.1 on igb0
    Jul 17 13:18:45 php-fpm 54733 /rc.linkup: DEVD Ethernet detached event for wan
    Jul 17 13:18:44 check_reload_status Linkup starting igb0
    Jul 17 13:18:44 kernel igb0: link state changed to DOWN


  • Netgate Administrator

    What do you see in the dhcp logs for dhclient at the time?

    Might be this: https://redmine.pfsense.org/issues/9267

    Steve



  • Thanks for the quick answer, here is the log:

    Jul 17 13:26:54 dhclient BOUND
    Jul 17 13:26:54 dhclient 75400 DHCPACK from 84.112.46.1
    Jul 17 13:26:54 dhclient 75400 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:26:54 dhclient ARPCHECK
    Jul 17 13:26:52 dhclient ARPSEND
    Jul 17 13:26:52 dhclient 75400 DHCPOFFER from 84.112.46.1
    Jul 17 13:26:52 dhclient 75400 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 2
    Jul 17 13:26:52 dhclient 75400 DHCPNAK from 10.34.113.33
    Jul 17 13:26:52 dhclient 75400 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:26:50 dhclient 75400 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:26:50 dhclient PREINIT
    Jul 17 13:26:42 dhclient 80196 exiting.
    Jul 17 13:26:42 dhclient 80196 connection closed
    Jul 17 13:26:33 dhcpleases Sending HUP signal to dns daemon(70110)
    Jul 17 13:26:33 dhcpd DHCPACK on 192.168.6.35 to 70:ee:50:16:45:4c (netatmo-welcome-16454c) via igb5
    Jul 17 13:26:33 dhcpd DHCPREQUEST for 192.168.6.35 from 70:ee:50:16:45:4c (netatmo-welcome-16454c) via igb5
    Jul 17 13:25:28 dhcpleases Sending HUP signal to dns daemon(70110)
    Jul 17 13:25:28 dhcpd DHCPACK on 192.168.6.42 to 70:ee:50:0d:aa:60 (Netatmo Relay) via igb5
    Jul 17 13:25:28 dhcpd DHCPREQUEST for 192.168.6.42 from 70:ee:50:0d:aa:60 (Netatmo Relay) via igb5
    Jul 17 13:23:43 dhcpd DHCPACK on 192.168.6.34 to e4:ce:8f:2c:d9:68 (ogi-it-oldmac) via igb5
    Jul 17 13:23:43 dhcpd DHCPREQUEST for 192.168.6.34 from e4:ce:8f:2c:d9:68 (ogi-it-oldmac) via igb5
    Jul 17 13:23:43 dhcpd reuse_lease: lease age 15746 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.6.34
    Jul 17 13:21:27 dhcpleases Sending HUP signal to dns daemon(70110)
    Jul 17 13:21:27 dhcpleases Sending HUP signal to dns daemon(70110)
    Jul 17 13:21:27 dhcpd Server starting service.
    Jul 17 13:21:27 dhcpd Sending on Socket/fallback/fallback-net
    Jul 17 13:21:27 dhcpd Sending on BPF/igb5/00:90:0b:3a:42:5b/192.168.6.0/24
    Jul 17 13:21:27 dhcpd Listening on BPF/igb5/00:90:0b:3a:42:5b/192.168.6.0/24
    Jul 17 13:21:27 dhcpd Wrote 40 leases to leases file.
    Jul 17 13:21:27 dhcpd Wrote 0 new dynamic host decls to leases file.
    Jul 17 13:21:27 dhcpd Wrote 0 deleted host decls to leases file.
    Jul 17 13:21:27 dhcpd For info, please visit https://www.isc.org/software/dhcp/
    Jul 17 13:21:27 dhcpd All rights reserved.
    Jul 17 13:21:27 dhcpd Copyright 2004-2018 Internet Systems Consortium.
    Jul 17 13:21:27 dhcpd Internet Systems Consortium DHCP Server 4.3.6-P1
    Jul 17 13:21:27 dhcpd PID file: /var/run/dhcpd.pid
    Jul 17 13:21:27 dhcpd Database file: /var/db/dhcpd.leases
    Jul 17 13:21:27 dhcpd Config file: /etc/dhcpd.conf
    Jul 17 13:21:27 dhcpd For info, please visit https://www.isc.org/software/dhcp/
    Jul 17 13:21:27 dhcpd All rights reserved.
    Jul 17 13:21:27 dhcpd Copyright 2004-2018 Internet Systems Consortium.
    Jul 17 13:21:27 dhcpd Internet Systems Consortium DHCP Server 4.3.6-P1
    Jul 17 13:21:26 dhcpleases Sending HUP signal to dns daemon(70110)
    Jul 17 13:21:26 dhcpleases kqueue error: unknown
    Jul 17 13:21:25 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    Jul 17 13:21:25 dhcpleases Sending HUP signal to dns daemon(88939)
    Jul 17 13:21:25 dhcpleases /etc/hosts changed size from original!
    Jul 17 13:21:23 dhclient 79311 bound: renewal in 111915 seconds.
    Jul 17 13:21:23 dhclient Deleting old routes
    Jul 17 13:21:22 dhclient New Routers (igb0): 84.112.46.1
    Jul 17 13:21:21 dhclient New Routers (igb0): 84.112.46.1
    Jul 17 13:21:21 dhclient New Broadcast Address (igb0): 255.255.255.255
    Jul 17 13:21:21 dhclient New Subnet Mask (igb0): 255.255.255.0
    Jul 17 13:21:21 dhclient New IP Address (igb0): 84.112.46.163
    Jul 17 13:21:21 dhclient ifconfig igb0 inet 84.112.46.163 netmask 255.255.255.0 broadcast 255.255.255.255
    Jul 17 13:21:21 dhclient Starting add_new_address()
    Jul 17 13:21:21 dhclient TIMEOUT
    Jul 17 13:21:21 dhclient 79311 Trying recorded lease 84.112.46.163
    Jul 17 13:21:21 dhclient 79311 No DHCPOFFERS received.
    Jul 17 13:21:16 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 5
    Jul 17 13:21:03 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 13
    Jul 17 13:20:55 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 8
    Jul 17 13:20:48 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 7
    Jul 17 13:20:38 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 10
    Jul 17 13:20:28 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 10
    Jul 17 13:20:24 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 4
    Jul 17 13:20:22 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 2
    Jul 17 13:20:21 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 1
    Jul 17 13:20:20 dhclient 79311 DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 1
    Jul 17 13:20:11 dhclient 79311 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:20:06 dhclient 79311 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:20:04 dhclient 79311 DHCPREQUEST on igb0 to 255.255.255.255 port 67
    Jul 17 13:20:04 dhclient PREINIT
    Jul 17 13:18:45 dhclient 24482 exiting.
    Jul 17 13:18:45 dhclient 24482 connection closed
    Jul 17 13:18:44 dhclient 35269 igb0 link state up -> down
    Jul 17 13:18:28 dhcpd DHCPACK on 192.168.6.43 to 70:70:0d:22:04:33 (Ogis-iPhone) via igb5

    What do you think?
    Thanks
    Ognian


  • Netgate Administrator

    Hmm, seems more like it's just not seeing any responses from the dhcp server when that happens.
    What did you do at 13:26 to allow it to get a lease?

    Steve



  • This is an issue that has plagued me here for some time. If my modem goes down for any period of time I have to restart the router to get it to grab an address.

    Its something that rarely happens but something that needs to be addressed. Ive always blamed something my ISP WaveBroadband was doing. Taking it down for testing is an issue here 24/7

    Watching now. :)



  • @stephenw10 I clicked on release lease and then on renew. Isn't there some kind of pinger wich would detect that situation and toggle Interface down and up?


  • Netgate Administrator

    Not that I'm aware of.

    Can you test a 2.5 snapshot? I don't think that fix has gone in yet but if it's something else it may already be fixed there.

    Steve



  • @stephenw10 OK will do that in a couple of hours... So I'll just go to "System Update" and select the 2.5 development snapshot. I'll take a config backup before. Any thing else?



  • @Ognian said in After Cable modem power down WAN Interface gets no ip:

    I clicked on release lease and then on renew. Isn't there some kind of pinger wich would detect that situation and toggle Interface down and up?

    Given that the DHCP process is starting indicates pfSense is seeing the modem come back. It's already sending out the requests which are not being responded to. There's nothing else it can do, so the problem is elsewhere. What happens if you plug a computer in? Does it get an address or not? This would indicate whether it's a pfSense problem.

    BTW, a DHCP release simply tells the server to release an address, it doesn't get anotther, as that's part of the normal DHCP process. You'd then have to do a renew to get an address.



  • @JKnott I'm nearly 100% sure that the problem is the way the modem comes up ;-) But if I want to have Internet in the 2 million people city I live, I have to accept this particular modem. No other way. So I'm searching for a pragmatic solution for this... In a couple of hours I'll have (hopefully) some time to check the 2.5 version; If there is no other way to do it I'll need a script pinging the first gateway and in case that it can't be reached toggling wan if down and up... I just thought that there is something like this already ...



  • This :

    a9263798-f49a-42b0-896b-72386b094bd0-image.png
    can't be used to make pfSense wait for slow-to-start upstream WAN devices ?



  • @stephenw10 Upgrade to
    2.5.0-DEVELOPMENT (amd64)
    built on Wed Jul 17 07:35:05 EDT 2019
    FreeBSD 12.0-RELEASE-p7
    went more or less smooth: after the last reboot there was no internet connection since the default gateway was on automatic instead of WAN_DHCP, but after that manual change it works like before.
    And yes it behaves exactly like with the 2.4.4 release, if the cable modem is powered down and again up the WAN interface ends with no ip. Looking on the dashboard after the gateway gets red, the WAN Interface gets an DHCP IP but after some time it drops to n/a...
    Shall I try to manually patch the script, or do you plan to have soon a new development version?



  • @Gertjan said in After Cable modem power down WAN Interface gets no ip:

    This :

    a9263798-f49a-42b0-896b-72386b094bd0-image.png
    can't be used to make pfSense wait for slow-to-start upstream WAN devices ?

    I had problem similar to this

    Jul 17 13:21:21	dhclient	79311	No DHCPOFFERS received.
    Jul 17 13:21:16	dhclient	79311	DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 5
    Jul 17 13:21:03	dhclient	79311	DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 13
    Jul 17 13:20:55	dhclient	79311	DHCPDISCOVER on igb0 to 255.255.255.255 port 67 interval 8
    

    where pfSense by default do DHCPDISCOVER no long enough compared to how long my modem starts. So setting timeout to 900 fixed it for me (in WAN interface options). Of course I can't tell that this will work for you. But it is worth the try :)



  • @Gertjan @tomashk Thank you so much! This works!!
    I've tried to search for the default value and the unit of this parameter; looks like the units are seconds and the default value is 60 seconds (from my log it looks like it waits 80 seconds, before it gives up). Changing this to 900 (15 minutes) should give plenty time to reconnect... And after changing it I can see that the cable modem needs almost 3 minutes to get online...

    So this looks like a good workaround for one time failures. Of course this https://redmine.pfsense.org/issues/9267 should do the rest


  • Netgate Administrator

    Nice! 👍


Log in to reply