Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    PfSense "dies" after new WAN IP / 2.0-RC2 (i386) built Sat Jun 18 05:49:09

    Scheduled Pinned Locked Moved
    2.0-RC Snapshot Feedback and Problems - RETIRED
    4
    15
    8.2k
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • W
      wallabybob
      last edited by

      @seh2000:

      I have attached the system.log as there are some - for me - strange entries in it, but I do not see reason in it to why reboot is needed, other log I shall try to get the next time?

      There are certainly some entries in your system log that I think are unusual:

      Jun  21 19:04:39 pfsense php: : Removing static route for monitor 192.168.100.1 and adding a new route through 200.75.108.1

      Not sure exactly what this means but it looks like your default gateway has been configured to be 200.75.108.1. That is confirmed by:

      Jun 21 19:04:42 pfsense php: : ROUTING: change default route to 200.75.108.1

      A little later:

      Jun 21 19:23:17 pfsense check_reload_status: Linkup starting re1
      Jun 21 19:23:17 pfsense kernel: re1: link state changed to DOWN
      Jun 21 19:23:19 pfsense php: : DEVD Ethernet detached event for wan
      Jun 21 19:23:19 pfsense dhclient[8494]: connection closed
      Jun 21 19:23:19 pfsense dhclient[8494]: connection closed
      Jun 21 19:23:19 pfsense dhclient[8494]: exiting.
      Jun 21 19:23:19 pfsense dhclient[8494]: exiting.

      The kernel thinks your device re1 has disappeared from the system (detached event). The startup reports re1 is on a PCI bus. Did you pull the card out? (or does FreeBSD now support PCI hotplug?)

      A little later (I have removed some lines):

      Jun 21 19:23:43 pfsense check_reload_status: Linkup starting re1
      Jun 21 19:23:43 pfsense kernel: re1: link state changed to UP
      Jun 21 19:23:45 pfsense php: : DEVD Ethernet attached event for wan
      Jun 21 19:23:45 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
      Jun 21 19:23:45 pfsense php: : HOTPLUG: Configuring interface wan

      re1 is back in the system.

      Then

      Jun 21 19:23:57 pfsense dhclient: ifconfig re1 inet 192.168.100.11 netmask 255.255.255.0 broadcast 192.168.100.255
      Jun 21 19:23:57 pfsense dhclient: New IP Address (re1): 192.168.100.11
      Jun 21 19:23:57 pfsense dhclient: New Routers (re1): 192.168.100.1

      Jun 21 19:23:57 pfsense dhclient: Adding new routes to interface: re1

      Jun 21 19:23:57 pfsense dhclient: /sbin/route add default 192.168.100.1

      So the WAN interface now has an IP address of 192.168.100.11 and the default gateway is now 192.168.100.1.

      Interesting: the default gateway has changed from a public IP address to a private IP address. Do you have two DHCP servers on your WAN subnet?

      Jun 21 19:23:57 pfsense dhclient[6075]: bound to 192.168.100.11 – renewal in 30 seconds.

      The DHCP lease time seems uncommonly short.

      At DHCP lease renewal time:

      Jun 21 19:24:54 pfsense dhclient[11432]: DHCPREQUEST on re1 to 255.255.255.255 port 67
      Jun 21 19:24:54 pfsense dhclient[11432]: DHCPACK from 200.75.108.1
      Jun 21 19:24:54 pfsense dhclient: New IP Address (re1): 200.75.108.164
      Jun 21 19:24:54 pfsense dhclient: New Subnet Mask (re1): 255.255.254.0
      Jun 21 19:24:54 pfsense dhclient: New Broadcast Address (re1): 200.75.109.255
      Jun 21 19:24:54 pfsense dhclient: New Routers (re1): 200.75.108.1
      Jun 21 19:24:54 pfsense dhclient: Adding new routes to interface: re1
      Jun 21 19:24:54 pfsense dhclient: /sbin/route add default 200.75.108.1
      Jun 21 19:24:54 pfsense dhclient[11432]: bound to 200.75.108.164 – renewal in 21600 seconds.

      Now re1 is back on a public IP subnet with a more reasonable DHCP lease time.

      I haven't looked into the source code for verification of this, but PERHAPS the

      Jun 21 19:24:55 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1

      type of message is saying some component is (ARP) looking for an IP address on some subnet other than those the interfaces belong to.

      Once I tried changing the WAN subnet through the console change IP address function but things didn't recover quickly and I resorted to reboot to clear it up.

      1 Reply Last reply Reply Quote 0
      • S
        seh2000
        last edited by

        Hi Wallabybob - many thanks for taking time to read any comment my logs…
        I have left a reply where I had something to say/ask.
        Steen

        @wallabybob:

        @seh2000:

        I have attached the system.log as there are some - for me - strange entries in it, but I do not see reason in it to why reboot is needed, other log I shall try to get the next time?

        There are certainly some entries in your system log that I think are unusual:

        Jun  21 19:04:39 pfsense php: : Removing static route for monitor 192.168.100.1 and adding a new route through 200.75.108.1
        Steen: Oops my sin I used first the private side of the cable modem for monitoring, but when I saw lots of issues I changed back to the GW IP…

        Not sure exactly what this means but it looks like your default gateway has been configured to be 200.75.108.1. That is confirmed by:

        Jun 21 19:04:42 pfsense php: : ROUTING: change default route to 200.75.108.1

        A little later:

        Jun 21 19:23:17 pfsense check_reload_status: Linkup starting re1
        Jun 21 19:23:17 pfsense kernel: re1: link state changed to DOWN
        Jun 21 19:23:19 pfsense php: : DEVD Ethernet detached event for wan
        Jun 21 19:23:19 pfsense dhclient[8494]: connection closed
        Jun 21 19:23:19 pfsense dhclient[8494]: connection closed
        Jun 21 19:23:19 pfsense dhclient[8494]: exiting.
        Jun 21 19:23:19 pfsense dhclient[8494]: exiting.
        Steen: Yes, the Cable Modem hands out new addresses quite often these days, issue I been posting about in other post, just got a new modem from ISP, but not sure if that fixed, but the issue is after each handout pfsense "dies" often a reboot is needed.

        The kernel thinks your device re1 has disappeared from the system (detached event). The startup reports re1 is on a PCI bus. Did you pull the card out? (or does FreeBSD now support PCI hotplug?)
        Steen: LoL, no no I did not pull the card out ;) my box got 4 gb ports, 1 on motherboard, and 3 on daughter board, no one touched the HW, but I seen this happen before for no reason really.
        Ideas?

        A little later (I have removed some lines):

        Jun 21 19:23:43 pfsense check_reload_status: Linkup starting re1
        Jun 21 19:23:43 pfsense kernel: re1: link state changed to UP
        Jun 21 19:23:45 pfsense php: : DEVD Ethernet attached event for wan
        Jun 21 19:23:45 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
        Jun 21 19:23:45 pfsense php: : HOTPLUG: Configuring interface wan

        re1 is back in the system.

        Then

        Jun 21 19:23:57 pfsense dhclient: ifconfig re1 inet 192.168.100.11 netmask 255.255.255.0 broadcast 192.168.100.255
        Jun 21 19:23:57 pfsense dhclient: New IP Address (re1): 192.168.100.11
        Jun 21 19:23:57 pfsense dhclient: New Routers (re1): 192.168.100.1

        Jun 21 19:23:57 pfsense dhclient: Adding new routes to interface: re1

        Jun 21 19:23:57 pfsense dhclient: /sbin/route add default 192.168.100.1

        So the WAN interface now has an IP address of 192.168.100.11 and the default gateway is now 192.168.100.1.

        Interesting: the default gateway has changed from a public IP address to a private IP address. Do you have two DHCP servers on your WAN subnet?

        Steen: 1st time I seen this but then again I have not kept traces running before, no idea why modem would hand out a private IP.
        And no I do not have 2 DHCP servers on the WAN the config is Cable Modem > pfSense > LAN/VoIP Box after the LAN port I have a HP switch

        Jun 21 19:23:57 pfsense dhclient[6075]: bound to 192.168.100.11 – renewal in 30 seconds.

        The DHCP lease time seems uncommonly short.
        Steen: Agree…not sure why

        At DHCP lease renewal time:

        Jun 21 19:24:54 pfsense dhclient[11432]: DHCPREQUEST on re1 to 255.255.255.255 port 67
        Jun 21 19:24:54 pfsense dhclient[11432]: DHCPACK from 200.75.108.1
        Jun 21 19:24:54 pfsense dhclient: New IP Address (re1): 200.75.108.164
        Jun 21 19:24:54 pfsense dhclient: New Subnet Mask (re1): 255.255.254.0
        Jun 21 19:24:54 pfsense dhclient: New Broadcast Address (re1): 200.75.109.255
        Jun 21 19:24:54 pfsense dhclient: New Routers (re1): 200.75.108.1
        Jun 21 19:24:54 pfsense dhclient: Adding new routes to interface: re1
        Jun 21 19:24:54 pfsense dhclient: /sbin/route add default 200.75.108.1
        Jun 21 19:24:54 pfsense dhclient[11432]: bound to 200.75.108.164 – renewal in 21600 seconds.

        Now re1 is back on a public IP subnet with a more reasonable DHCP lease time.
        Steen: Guess this after everything became stable…

        I haven't looked into the source code for verification of this, but PERHAPS the

        Jun 21 19:24:55 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1

        type of message is saying some component is (ARP) looking for an IP address on some subnet other than those the interfaces belong to.

        Once I tried changing the WAN subnet through the console change IP address function but things didn't recover quickly and I resorted to reboot to clear it up.
        Steen: Did not play with the console during the above event.

        1 Reply Last reply Reply Quote 0
        • W
          wallabybob
          last edited by

          @seh2000:

          Jun  21 19:04:39 pfsense php: : Removing static route for monitor 192.168.100.1 and adding a new route through 200.75.108.1
          Steen: Oops my sin I used first the private side of the cable modem for monitoring, but when I saw lots of issues I changed back to the GW IP…

          The log is supposed to be an example of pfSense dying after new WAN IP but you were messing around with it as well?

          @seh2000:

          Steen: Yes, the Cable Modem hands out new addresses quite often these days, issue I been posting about in other post, just got a new modem from ISP, but not sure if that fixed, but the issue is after each handout pfsense "dies" often a reboot is needed.

          I can't tell from the log which address change is from the cable modem and which is from you swapping to/from the "monitor" port.

          @seh2000:

          Steen: Did not play with the console during the above event.

          I was just relating my experience of my pfSense not recovering cleanly after an attempt to change the WAN interface's subnet. I thought it might be relevant because the log shows the subnet of the WAN interface on your pfSense changed significantly.

          I suggest you powerdown the cable modem and shutdown the pfSense box, make sure the pfSense box is connected to the non-monitoring port of the cable modem, powerup both boxes and leave it alone. If the problem recurs then post the corresponding logs.

          I gather cable modems typically have a broadcast segment shared by a number of premises. Its possible one of your neighbours has a DHCP server connected to their cable modem and it is handing out DHCP addresses to your pfSense box. Should your pfSense WAN interface have a private IP address (e.g. 192.168.100.x) or a public IP address (e.g. 200.75.108.x)? If a public address, why not enable Block private networks on your WAN interface (Interfaces -> WAN, near the bottom of the page) save and reboot. That should stop some rogue DHCP servers messing you up. You might need to talk to tech support at your ISP to get more details of how DHCP is supposed to work for you. They might have some clues about the private address and the 30 second renewal time.

          1 Reply Last reply Reply Quote 0
          • S
            seh2000
            last edited by

            @wallabybob:

            @seh2000:

            Jun  21 19:04:39 pfsense php: : Removing static route for monitor 192.168.100.1 and adding a new route through 200.75.108.1
            Steen: Oops my sin I used first the private side of the cable modem for monitoring, but when I saw lots of issues I changed back to the GW IP…

            The log is supposed to be an example of pfSense dying after new WAN IP but you were messing around with it as well?

            Sorry my super mistake.  :-[  :-[
            This morning I got the same problem again, got some log, will edit and attach later.

            [quote author=seh2000 link=topic=37948.msg196495#msg196495 date=1308796535]
            Steen: Yes, the Cable Modem hands out new addresses quite often these days, issue I been posting about in other post, just got a new modem from ISP, but not sure if that fixed, but the issue is after each handout pfsense "dies" often a reboot is needed.

            I can't tell from the log which address change is from the cable modem and which is from you swapping to/from the "monitor" port.

            Understood my bad.

            @seh2000:

            Steen: Did not play with the console during the above event.

            I was just relating my experience of my pfSense not recovering cleanly after an attempt to change the WAN interface's subnet. I thought it might be relevant because the log shows the subnet of the WAN interface on your pfSense changed significantly.

            I suggest you powerdown the cable modem and shutdown the pfSense box, make sure the pfSense box is connected to the non-monitoring port of the cable modem, powerup both boxes and leave it alone. If the problem recurs then post the corresponding logs.

            Done that several times before I even posted here. Will post logs later.

            I gather cable modems typically have a broadcast segment shared by a number of premises. Its possible one of your neighbours has a DHCP server connected to their cable modem and it is handing out DHCP addresses to your pfSense box. Should your pfSense WAN interface have a private IP address (e.g. 192.168.100.x) or a public IP address (e.g. 200.75.108.x)? If a public address, why not enable Block private networks on your WAN interface (Interfaces -> WAN, near the bottom of the page) save and reboot. That should stop some rogue DHCP servers messing you up. You might need to talk to tech support at your ISP to get more details of how DHCP is supposed to work for you. They might have some clues about the private address and the 30 second renewal time.

            OK, let me see, perhaps start from the bottom first.
            In other post I explained the situation. My ISP really do not care too much about problems as he is the only provider in the area I live and he knows. Most of his technical staff have no clue on what they do. No training, etc. His NOC is poorly run and the installers are from 3rd party companies who can only do basic cable installations. For one year I pointed out to him each time I paid (monthly) that he had a router in his network that was faulty as I kept running traces that clearly showed the number of packet lost and the delay inside his network. After a year he fixed the router. 
            So I am most of the time left alone to try to "fix" problems - I requested for 6 months a replacement of my modem, got it last week. Because the same technician that came had been here 20 times and I saw he got a test modem.
            Sorry to long…
            OK - the Block private networks was done at set-up and its still selected.
            I will try to speak with same technician again as I also have the modem logs that shows the same time as the pfsense logs for events.
            For the private IP then and please correct me if I am wrong, the modem will hand out a private IP when for one or the other reason the connection upstream is not there.

            1 Reply Last reply Reply Quote 0
            • W
              wallabybob
              last edited by

              @seh2000:

              OK - the Block private networks was done at set-up and its still selected.

              When I enable Block private networks on my system it adds a new rule (first rule) on the interface to block all traffic from RFC 1918 networks. This rule should block the DHCP traffic from servers with a private IP address.
              Can you explain how you have Block private networks enabled on WAN and DHCP traffic from a server with a private IP address is getting through the firewall rule on the WAN interface?

              @seh2000:

              For the private IP then and please correct me if I am wrong, the modem will hand out a private IP when for one or the other reason the connection upstream is not there.

              I've no idea if your cable modem is supposed to do that. A manual might discuss that. What cable modem are you using? If it does hand out a private IP to DHCP requests when the upstream connection is lost how does it decide what IP address and subnet to use?

              1 Reply Last reply Reply Quote 0
              • S
                seh2000
                last edited by

                @wallabybob:

                @seh2000:

                OK - the Block private networks was done at set-up and its still selected.

                When I enable Block private networks on my system it adds a new rule (first rule) on the interface to block all traffic from RFC 1918 networks. This rule should block the DHCP traffic from servers with a private IP address.
                Can you explain how you have Block private networks enabled on WAN and DHCP traffic from a server with a private IP address is getting through the firewall rule on the WAN interface?

                I cannot explain this, but a cable modem will hand out a Private IP if it loses sync with ISP in order to keep Local Network up and running. So the Private IP's indicates I am somehow losing connection, from Cable Modem to ISP.

                Here a "few" lines from system.log soon two hours ago.

                Jun 23 09:57:57 pfsense apinger: ALARM: WAN(200.75.108.1)  *** down ***
                Jun 23 09:58:07 pfsense check_reload_status: Reloading filter
                Jun 23 09:58:24 pfsense check_reload_status: Linkup starting re1
                Jun 23 09:58:24 pfsense kernel: re1: link state changed to DOWN
                Jun 23 09:58:25 pfsense check_reload_status: Linkup starting re1
                Jun 23 09:58:25 pfsense kernel: re1: link state changed to UP

                then

                Jun 23 09:58:28 pfsense php: : HOTPLUG: Configuring interface wan
                Jun 23 09:58:28 pfsense dhclient: PREINIT
                Jun 23 09:58:28 pfsense dhclient[29254]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                Jun 23 09:58:28 pfsense dhclient[29254]: DHCPNAK from 192.168.100.1
                Jun 23 09:58:28 pfsense dhclient[29254]: DHCPDISCOVER on re1 to 255.255.255.255 port 67 interval 1
                Jun 23 09:58:28 pfsense dhclient[29254]: DHCPOFFER from 192.168.100.1
                Jun 23 09:58:28 pfsense dhclient: ARPSEND
                Jun 23 09:58:30 pfsense dhclient: ARPCHECK
                Jun 23 09:58:30 pfsense dhclient[29254]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                Jun 23 09:58:31 pfsense dhclient[29254]: DHCPACK from 192.168.100.1
                Jun 23 09:58:31 pfsense dhclient: BOUND
                Jun 23 09:58:31 pfsense dhclient: Starting add_new_address()
                Jun 23 09:58:31 pfsense dhclient: ifconfig re1 inet 192.168.100.11 netmask 255.255.255.0 broadcast 192.168.100.255
                Jun 23 09:58:31 pfsense dhclient: New IP Address (re1): 192.168.100.11
                Jun 23 09:58:31 pfsense dhclient: New Subnet Mask (re1): 255.255.255.0
                Jun 23 09:58:31 pfsense dhclient: New Broadcast Address (re1): 192.168.100.255
                Jun 23 09:58:31 pfsense dhclient: New Routers (re1): 192.168.100.1
                Jun 23 09:58:31 pfsense dhclient: Adding new routes to interface: re1
                Jun 23 09:58:31 pfsense dhclient: /sbin/route add default 192.168.100.1
                Jun 23 09:58:31 pfsense dhclient: Creating resolv.conf
                Jun 23 09:58:31 pfsense check_reload_status: rc.newwanip starting re1
                Jun 23 09:58:31 pfsense dhclient[29254]: bound to 192.168.100.11 – renewal in 30 seconds.
                Jun 23 09:58:32 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1

                then more

                Jun 23 09:58:35 pfsense dnsmasq[55044]: using nameserver 8.8.8.8#53
                Jun 23 09:58:36 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:36 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:36 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:36 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:37 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:38 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:38 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:38 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:39 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:58:39 pfsense php: : Resyncing OpenVPN instances for interface WAN.

                The entry for OpenVPN no idea why, I am not having OpenVPN op/running/using.

                then more more

                Jun 23 09:59:01 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:59:01 pfsense dhclient[34921]: DHCPREQUEST on re1 to 192.168.100.1 port 67
                Jun 23 09:59:02 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:59:02 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:59:02 pfsense dhclient[34921]: DHCPREQUEST on re1 to 192.168.100.1 port 67
                Jun 23 09:59:03 pfsense dhclient[34921]: DHCPACK from 192.168.100.1
                Jun 23 09:59:03 pfsense dhclient: RENEW
                Jun 23 09:59:03 pfsense dhclient: Creating resolv.conf
                Jun 23 09:59:03 pfsense dhclient[34921]: bound to 192.168.100.11 – renewal in 30 seconds.

                So pfsense still tries to get hole to WAN 200.75.108.1 (I think) and then

                Jun 23 09:59:39 pfsense dhclient[34921]: DHCPREQUEST on re1 to 192.168.100.1 port 67
                Jun 23 09:59:40 pfsense apinger: ALARM: WAN(192.168.100.1)  *** delay ***
                Jun 23 09:59:41 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 09:59:42 pfsense dhclient[34921]: DHCPREQUEST on re1 to 192.168.100.1 port 67
                Jun 23 09:59:43 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1

                Stille arpresolver tries for the "old" WAN IP and then

                Jun 23 10:00:00 pfsense dhclient[34921]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                Jun 23 10:00:00 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:00 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:00 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:00 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:02 pfsense check_reload_status: Reloading filter
                Jun 23 10:00:04 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:04 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                Jun 23 10:00:04 pfsense dhclient: EXPIRE
                Jun 23 10:00:04 pfsense dhclient: Deleting old routes
                Jun 23 10:00:04 pfsense dhclient: PREINIT
                Jun 23 10:00:04 pfsense dhclient[34921]: DHCPDISCOVER on re1 to 255.255.255.255 port 67 interval 1
                Jun 23 10:00:05 pfsense dhclient[34921]: DHCPDISCOVER on re1 to 255.255.255.255 port 67 interval 2
                Jun 23 10:00:05 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1

                Finally here dhclient seams to expire the info for old WAN, but then the new IP is strange 255.255.255.255 and then back to the private IP, then this goes on and on and at last

                Jun 23 10:07:20 pfsense apinger: ALARM: WAN(192.168.100.1)  *** down ***
                Jun 23 10:07:21 pfsense dhclient: ARPCHECK
                Jun 23 10:07:21 pfsense dhclient[56553]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                Jun 23 10:07:21 pfsense dhclient[56553]: DHCPACK from 200.75.108.1
                Jun 23 10:07:21 pfsense dhclient: BOUND
                Jun 23 10:07:21 pfsense dhclient: Deleting old routes
                Jun 23 10:07:21 pfsense dhclient: Starting add_new_address()
                Jun 23 10:07:21 pfsense dhclient: ifconfig re1 inet 200.75.108.164 netmask 255.255.254.0 broadcast 200.75.109.255
                Jun 23 10:07:21 pfsense dhclient: New IP Address (re1): 200.75.108.164
                Jun 23 10:07:21 pfsense dhclient: New Subnet Mask (re1): 255.255.254.0
                Jun 23 10:07:21 pfsense dhclient: New Broadcast Address (re1): 200.75.109.255
                Jun 23 10:07:21 pfsense dhclient: New Routers (re1): 200.75.108.1
                Jun 23 10:07:21 pfsense dhclient: Adding new routes to interface: re1
                Jun 23 10:07:21 pfsense dhclient: /sbin/route add default 200.75.108.1
                Jun 23 10:07:21 pfsense dhclient: Creating resolv.conf
                Jun 23 10:07:21 pfsense check_reload_status: rc.newwanip starting re1
                Jun 23 10:07:21 pfsense dhclient[56553]: bound to 200.75.108.164 – renewal in 21600 seconds.
                Jun 23 10:07:23 pfsense php: : rc.newwanip: Informational is starting re1.
                Jun 23 10:07:23 pfsense php: : rc.newwanip: on (IP address: 200.75.108.164) (interface: wan) (real interface: re1).
                Jun 23 10:07:23 pfsense dnsmasq[55044]: reading /etc/resolv.conf
                Jun 23 10:07:23 pfsense dnsmasq[55044]: using nameserver 8.8.2.2#53
                Jun 23 10:07:23 pfsense dnsmasq[55044]: using nameserver 4.2.2.4#53
                Jun 23 10:07:23 pfsense dnsmasq[55044]: using nameserver 8.8.8.8#53
                Jun 23 10:07:23 pfsense php: : ROUTING: change default route to 200.75.108.1

                Back online…system.log attached as it too many lines to post.
                This time I had not to do anything with pfsense, most times pfsense needs to have a manual release/renew on the WAN interface to get back online as despite the modem is back pfsense keeps seeing either the "old" WAN IP or the Private IP.

                @seh2000:

                For the private IP then and please correct me if I am wrong, the modem will hand out a private IP when for one or the other reason the connection upstream is not there.

                I've no idea if your cable modem is supposed to do that. A manual might discuss that. What cable modem are you using? If it does hand out a private IP to DHCP requests when the upstream connection is lost how does it decide what IP address and subnet to use?

                The "new" modem is Motorola SB5101.

                This is what I have understood, when a cable modem has lost sync on the Cable i/f side, the modem hands out a 192.168.100.x address to any DHCP client requesting it. Indeed, the logs shows that pfsense immediately releases the Public IP from its WAN interface within seconds of the modem handing out the Private IP, then pfsense starts DHCP Discover, when the modem sees the Discovers the Private IP is Offered.
                But the difference is that this lease is very, very short, 30 or less seconds. But pfsense is supposed to honor that lease and, after expiration, ask for a new IP address. If everything has gone okay on the Modem side (resync with ISP), then pfsense should go through DHCP DORA again.
                But sometimes I don't think pfsense does  or for some reason pfsense specifically requesting the same Private IP again. I am unsure, but it seams that pfsense for a long time remembers the old WAN IP.
                It seams also all this eats a bunch of resources as everything becomes slow and non responsive e.g. going from Dashboard to Systems Log takes many seconds…

                [system.log 06232011 1113am sh.txt](/public/imported_attachments/1/system.log 06232011 1113am sh.txt)

                1 Reply Last reply Reply Quote 0
                • S
                  seh2000
                  last edited by

                  OK, I have done the following tests:

                  1. Disconnected Connection from Cable Modem Private Side

                  2. Disconnected Connection from Cable Modem Public Side

                  I disconnected from the Private Side at 14:50:00, pfsense "sees" this more or less immediately
                  [from system.log]
                  Jun 23 14:50:01 pfsense php: : DEVD Ethernet detached event for wan
                  then
                  Jun 23 14:50:21 pfsense php: : Could not find gateway for interface(wan)
                  then many of
                  Jun 23 14:50:23 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  then
                  Jun 23 14:59:04 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 14:59:05 pfsense check_reload_status: Linkup starting re1
                  Jun 23 14:59:05 pfsense kernel: re1: link state changed to UP
                  Jun 23 14:59:07 pfsense php: : DEVD Ethernet attached event for wan
                  Jun 23 14:59:07 pfsense php: : HOTPLUG: Configuring interface wan
                  Jun 23 14:59:07 pfsense dhclient: PREINIT
                  Jun 23 14:59:07 pfsense dhclient[23721]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                  Jun 23 14:59:07 pfsense dhclient[23721]: DHCPACK from 200.75.108.1
                  Jun 23 14:59:07 pfsense dhclient: REBOOT
                  Jun 23 14:59:07 pfsense dhclient: Starting add_new_address()
                  Jun 23 14:59:07 pfsense dhclient: ifconfig re1 inet 200.75.108.164 netmask 255.255.254.0 broadcast 200.75.109.255
                  Jun 23 14:59:07 pfsense dhclient: New IP Address (re1): 200.75.108.164
                  Jun 23 14:59:07 pfsense dhclient: New Subnet Mask (re1): 255.255.254.0
                  Jun 23 14:59:07 pfsense dhclient: New Broadcast Address (re1): 200.75.109.255
                  Jun 23 14:59:07 pfsense dhclient: New Routers (re1): 200.75.108.1
                  Jun 23 14:59:07 pfsense dhclient: Adding new routes to interface: re1
                  Jun 23 14:59:07 pfsense dhclient: /sbin/route add default 200.75.108.1
                  Jun 23 14:59:07 pfsense dhclient: Creating resolv.conf
                  Jun 23 14:59:07 pfsense check_reload_status: rc.newwanip starting re1
                  Jun 23 14:59:07 pfsense dhclient[23721]: bound to 200.75.108.164 – renewal in 21600 seconds.
                  Jun 23 14:59:07 pfsense apinger: alarm canceled: WAN(200.75.108.1)  *** down ***
                  Jun 23 14:59:09 pfsense php: : rc.newwanip: Informational is starting re1.
                  Jun 23 14:59:09 pfsense php: : rc.newwanip: on (IP address: 200.75.108.164) (interface: wan) (real interface: re1).
                  Jun 23 14:59:10 pfsense php: : ROUTING: change default route to 200.75.108.1
                  Jun 23 14:59:10 pfsense check_reload_status: Reloading filter

                  Back online and GUI fully normal responsive.

                  Disconnected Connection from Cable Modem Public Side at 15:00:00 and pfsense "sees" this more less immediately
                  [from system.log]
                  Jun 23 15:00:21 pfsense apinger: ALARM: WAN(200.75.108.1)  *** down ***
                  then
                  Jun 23 15:00:31 pfsense check_reload_status: Reloading filter
                  Jun 23 15:00:46 pfsense check_reload_status: Linkup starting re1
                  Jun 23 15:00:46 pfsense kernel: re1: link state changed to DOWN
                  Jun 23 15:00:48 pfsense check_reload_status: Linkup starting re1
                  Jun 23 15:00:48 pfsense kernel: re1: link state changed to UP
                  Jun 23 15:00:48 pfsense php: : DEVD Ethernet detached event for wan
                  Jun 23 15:00:48 pfsense dhclient[23761]: connection closed
                  Jun 23 15:00:48 pfsense dhclient[23761]: connection closed
                  Jun 23 15:00:48 pfsense dhclient[23761]: exiting.
                  Jun 23 15:00:48 pfsense dhclient[23761]: exiting.
                  Jun 23 15:00:50 pfsense php: : DEVD Ethernet attached event for wan
                  Jun 23 15:00:50 pfsense php: : HOTPLUG: Configuring interface wan
                  Jun 23 15:00:50 pfsense dhclient: PREINIT
                  Jun 23 15:00:50 pfsense dhclient[40721]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                  Jun 23 15:00:50 pfsense dhclient[40721]: DHCPNAK from 192.168.100.1
                  Jun 23 15:00:50 pfsense dhclient[40721]: DHCPDISCOVER on re1 to 255.255.255.255 port 67 interval 1
                  Jun 23 15:00:50 pfsense dhclient[40721]: DHCPOFFER from 192.168.100.1
                  Jun 23 15:00:50 pfsense dhclient: ARPSEND
                  Jun 23 15:00:50 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 15:00:51 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 15:00:52 pfsense dhclient: ARPCHECK
                  Jun 23 15:00:52 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 15:00:52 pfsense dhclient[40721]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                  Jun 23 15:00:53 pfsense dhclient[40721]: DHCPACK from 192.168.100.1
                  Jun 23 15:00:53 pfsense dhclient: BOUND
                  Jun 23 15:00:53 pfsense dhclient: Starting add_new_address()
                  Jun 23 15:00:53 pfsense dhclient: ifconfig re1 inet 192.168.100.11 netmask 255.255.255.0 broadcast 192.168.100.255
                  Jun 23 15:00:53 pfsense dhclient: New IP Address (re1): 192.168.100.11
                  Jun 23 15:00:53 pfsense dhclient: New Subnet Mask (re1): 255.255.255.0
                  Jun 23 15:00:53 pfsense dhclient: New Broadcast Address (re1): 192.168.100.255
                  Jun 23 15:00:53 pfsense dhclient: New Routers (re1): 192.168.100.1
                  Jun 23 15:00:53 pfsense dhclient: Adding new routes to interface: re1
                  Jun 23 15:00:53 pfsense dhclient: /sbin/route add default 192.168.100.1
                  Jun 23 15:00:53 pfsense dhclient: Creating resolv.conf
                  Jun 23 15:00:53 pfsense check_reload_status: rc.newwanip starting re1
                  Jun 23 15:00:53 pfsense dhclient[40721]: bound to 192.168.100.11 – renewal in 30 seconds.

                  So as per other post then the Cable Modem will "assign" the Private IP, from what I can see then this is correct and pfsense starts acting accordingly, but then

                  Jun 23 15:00:56 pfsense apinger: Exiting on signal 15.
                  Jun 23 15:00:56 pfsense dnsmasq[55044]: reading /etc/resolv.conf
                  Jun 23 15:00:56 pfsense dnsmasq[55044]: using nameserver 8.8.2.2#53
                  Jun 23 15:00:56 pfsense dnsmasq[55044]: using nameserver 4.2.2.4#53
                  Jun 23 15:00:56 pfsense dnsmasq[55044]: using nameserver 8.8.8.8#53
                  Jun 23 15:00:56 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 15:00:56 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1
                  Jun 23 15:00:57 pfsense check_reload_status: Reloading filter
                  Jun 23 15:00:57 pfsense apinger: Starting Alarm Pinger, apinger(50726)
                  Jun 23 15:00:57 pfsense kernel: arpresolve: can't allocate llinfo for 200.75.108.1

                  From here the WEB GUI becomes sluggish I cannot see any large CPU not Drive activity so it must be somewhere else.
                  And arpresolve keeps looking for the "old" Public IP (WAN IP).

                  Then at 15:10 I reconnect the Cable from ISP to the Cable Modem and pfsense "sees" this:

                  Jun 23 15:10:32 pfsense dhclient[45159]: DHCPREQUEST on re1 to 192.168.100.1 port 67
                  Jun 23 15:10:44 pfsense dhclient: EXPIRE
                  Jun 23 15:10:44 pfsense dhclient: Deleting old routes
                  Jun 23 15:10:44 pfsense dhclient: PREINIT
                  Jun 23 15:10:44 pfsense dhclient[45159]: DHCPDISCOVER on re1 to 255.255.255.255 port 67 interval 1
                  Jun 23 15:10:44 pfsense dhclient[45159]: DHCPOFFER from 200.75.108.1
                  Jun 23 15:10:44 pfsense dhclient: ARPSEND
                  Jun 23 15:10:45 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1
                  Jun 23 15:10:46 pfsense dhclient: ARPCHECK
                  Jun 23 15:10:46 pfsense dhclient[45159]: DHCPREQUEST on re1 to 255.255.255.255 port 67
                  Jun 23 15:10:46 pfsense dhclient[45159]: DHCPACK from 200.75.108.1
                  Jun 23 15:10:46 pfsense dhclient: BOUND
                  Jun 23 15:10:46 pfsense dhclient: Deleting old routes
                  Jun 23 15:10:46 pfsense dhclient: Starting add_new_address()
                  Jun 23 15:10:46 pfsense dhclient: ifconfig re1 inet 200.75.108.164 netmask 255.255.254.0 broadcast 200.75.109.255
                  Jun 23 15:10:46 pfsense dhclient: New IP Address (re1): 200.75.108.164
                  Jun 23 15:10:46 pfsense dhclient: New Subnet Mask (re1): 255.255.254.0
                  Jun 23 15:10:46 pfsense dhclient: New Broadcast Address (re1): 200.75.109.255
                  Jun 23 15:10:46 pfsense dhclient: New Routers (re1): 200.75.108.1
                  Jun 23 15:10:46 pfsense dhclient: Adding new routes to interface: re1
                  Jun 23 15:10:46 pfsense dhclient: /sbin/route add default 200.75.108.1
                  Jun 23 15:10:46 pfsense dhclient: Creating resolv.conf
                  Jun 23 15:10:46 pfsense check_reload_status: rc.newwanip starting re1
                  Jun 23 15:10:46 pfsense dhclient[45159]: bound to 200.75.108.164 – renewal in 21600 seconds.
                  Jun 23 15:10:46 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1
                  Jun 23 15:10:48 pfsense kernel: arpresolve: can't allocate llinfo for 192.168.100.1
                  Jun 23 15:10:48 pfsense php: : rc.newwanip: Informational is starting re1.
                  Jun 23 15:10:48 pfsense php: : rc.newwanip: on (IP address: 200.75.108.164) (interface: wan) (real interface: re1).
                  Jun 23 15:10:48 pfsense php: : ROUTING: change default route to 200.75.108.1
                  Jun 23 15:10:48 pfsense apinger: Exiting on signal 15.

                  And back online, but I cannot simulate when the Cable Modem drop connection due to issues in the cable net nor the reboot that follows, this might have a different result. However, more often than not I have to do a manual "Release" then "Renew" of WAN interface, and whole period as mentioned before the WEB GUI is practically none responsive, or it takes several seconds between screens. In the log shows only one of the times I tried to log in and out, that is also strange...but a minor issue the real one is pfsense not starting to route traffic most times without the above mentioned "Release & Renew" of the WAN interface.

                  Steen

                  [system.log 06232011 1512pm sh.txt](/public/imported_attachments/1/system.log 06232011 1512pm sh.txt)

                  1 Reply Last reply Reply Quote 0
                  • H
                    heper
                    last edited by

                    the sluggishness is most likely because pfsense can not contact any of the configured dns servers

                    1 Reply Last reply Reply Quote 0
                    • S
                      seh2000
                      last edited by

                      @heper:

                      the sluggishness is most likely because pfsense can not contact any of the configured dns servers

                      Hi heper,
                      Thanks for your response!

                      OK, so is this normal behavior or unnormal behavior?

                      But then why no sluggishness when the LAN Cable is pulled from Cable Modem?
                      And then why sluggishness only when WAN lost?

                      When sluggishness I saw with wireshark the data flow between PC/Mac the webgui been garbled e.g. data loss, lots of retransmissions, etc.

                      When LAN Cable pulled everything works OK, pfsense reports connection disconencted and accepts, but when WAN lost then processes like arpresolve keeps trying "old" WAN IP?

                      The "switchover" to private IP works fine after WAN lost, but the following events sees strange out to me, but I guess it should be so, but still there is a problem during the period under private IP and often the only way back to online is a manual Release/Renew of WAN connection.
                      That is really an big issue.
                      I tried same with an old linksys wrt-54gl with dd-wrt firmware understand this is a much more simpler solution also why I no longer use, but I saw no sluggishness, no garbled data between box and webgui, and a behavior when WAN lost pretty similar to when LAN Cable pulled from Cable Modem.

                      Wonder if others with Cable Modem connections could try same tests as I did?

                      Sorry for the long response I did not mean to bang bang bang to you heper! I just got carried away  :-[

                      Steen

                      1 Reply Last reply Reply Quote 0
                      • E
                        eri--
                        last edited by

                        Please do not complain in vain here and provide a packet trace when this happens.

                        1 Reply Last reply Reply Quote 0
                        • S
                          seh2000
                          last edited by

                          @ermal:

                          Please do not complain in vain here and provide a packet trace when this happens.

                          Hmmm - sorry this was not to be received as a complaint in vain or as a complaint merely to open an discussion by posting some additional questions and to tell heper I was not trying to be unpolite to him with my long reply, I assumed and my bad if what I have written and copied from traces and logs so far does not cover what is needed. I am not a developer nor a Linux specialist, but I try my best.

                          1 Reply Last reply Reply Quote 0
                          • S
                            seh2000
                            last edited by

                            Hi,

                            After I am on 2.0-RC3  (i386) built on Fri Jul 8 19:24:31 EDT 2011 and my Modem was swapped, the Amplifier my drop sits on was changed twice I have not had this problem.

                            BR// Steen

                            1 Reply Last reply Reply Quote 0
                            • First post
                              Last post