I see a race condition (of sorts) in that log output - dyn update is happening (triggered, anyway) before the i/f is fully up. -Adam
(Sorry for the top-post, as usual. BTW, none of the Android email clients that support old-style replies work properly on the new version :-(.) Jeppe Øland <[email protected]> wrote: >>> Yes. We'd have thousands of people screaming if that wasn't the case, >>> and I've never seen that not work. /etc/rc.newwanip runs when any IP >>> changes, which does the update. It's not shown there in your log. When >>> it runs it logs, not sure how much you snipped out. >> >> Since some of us have the problem, there's obviously something going on. > >ISP had DHCP problems again yesterday and today, and yet again pfSense >failed to update! > >Log from yesterday (System was rebooted the box to see if the problem >was local): >(Snipped a bunch of repeated or irrelevant lines) > >Oct 19 07:28:12 dhcpd: For info, please visit >https://www.isc.org/software/dhcp/ >Oct 19 07:28:12 dhcpleases: Could not deliver signal HUP to process >because its pidfile does not exist, No such file or directory. >Oct 19 07:28:12 dhcpleases: Could not deliver signal HUP to process >because its pidfile does not exist, No such file or directory. >Oct 19 07:28:12 check_reload_status: Updating all dyndns >Oct 19 07:28:12 dnsmasq[41848]: started, version 2.55 cachesize 10000 >Oct 19 07:28:12 dnsmasq[41848]: compile time options: IPv6 GNU-getopt >no-DBus I18N DHCP TFTP >Oct 19 07:28:12 dnsmasq[41848]: reading /etc/resolv.conf >Oct 19 07:28:12 dnsmasq[41848]: using nameserver 8.8.4.4#53 >Oct 19 07:28:12 dnsmasq[41848]: using nameserver 8.8.8.8#53 >Oct 19 07:28:12 dnsmasq[41848]: using nameserver 8.8.4.4#53 >Oct 19 07:28:12 dnsmasq[41848]: using nameserver 8.8.8.8#53 >Oct 19 07:28:12 dnsmasq[41848]: ignoring nameserver 127.0.0.1 - local >interface >Oct 19 07:28:12 dnsmasq[41848]: ignoring nameserver 127.0.0.1 - local >interface >Oct 19 07:28:12 dnsmasq[41848]: read /etc/hosts - 17 addresses >Oct 19 07:28:13 check_reload_status: Linkup starting em0 >Oct 19 07:28:13 kernel: em0: link state changed to UP >Oct 19 07:28:17 php: : DynDns: updatedns() starting >Oct 19 07:28:17 php: : There was an error trying to determine the IP >for interface - wan(em1_vlan1001). Probably interface has no ip or is >down. Dyndns update not possible for dyndns. >Oct 19 07:28:27 php: : OpenNTPD is starting up. >Oct 19 07:28:29 check_reload_status: Restarting ipsec tunnels >Oct 19 07:28:32 php: : Creating rrd update script >Oct 19 07:28:32 kernel: p4tcc0: <CPU Frequency Thermal Control> on cpu0 >Oct 19 07:28:32 kernel: p4tcc1: <CPU Frequency Thermal Control> on cpu1 >Oct 19 07:28:32 kernel: p4tcc2: <CPU Frequency Thermal Control> on cpu2 >Oct 19 07:28:32 kernel: p4tcc3: <CPU Frequency Thermal Control> on cpu3 >Oct 19 07:28:33 php: : Restarting/Starting all packages. >Oct 19 07:28:34 login: login on ttyv0 as root >Oct 19 07:28:34 sshlockout[24879]: sshlockout/webConfigurator v3.0 >starting up >Oct 19 07:28:35 php: : IPSEC: One or more IPsec tunnel endpoints has >changed its IP. Refreshing. >Oct 19 07:28:37 check_reload_status: Reloading filter >Oct 19 07:28:44 dnsmasq[41848]: read /etc/hosts - 23 addresses >Oct 19 07:29:10 dhclient: FAIL >Oct 19 07:29:34 php: /index.php: Successful webConfigurator login for >user 'admin' from 10.10.10.10 >Oct 19 07:29:34 php: /index.php: Successful webConfigurator login for >user 'admin' from 10.10.10.10 >Oct 19 07:30:12 dhclient: FAIL >Oct 19 07:31:14 dhclient: FAIL >Oct 19 07:55:52 dhclient: ARPSEND >Oct 19 07:55:54 dhclient: ARPCHECK >Oct 19 07:57:10 dhclient: FAIL >Oct 19 07:58:12 dhclient: FAIL >Oct 19 09:03:37 dhclient: ARPSEND >Oct 19 09:03:39 dhclient: ARPCHECK >Oct 19 09:03:39 dhclient: BOUND >Oct 19 09:03:39 dhclient: Starting add_new_address() >Oct 19 09:03:39 dhclient: ifconfig em1_vlan1001 inet <IP_OLD> netmask ><MASK> broadcast <BROADCAST> >Oct 19 09:03:39 dhclient: New IP Address (em1_vlan1001): <IP_OLD> >Oct 19 09:03:39 dhclient: New Subnet Mask (em1_vlan1001): <MASK> >Oct 19 09:03:39 dhclient: New Broadcast Address (em1_vlan1001): ><BROADCAST> >Oct 19 09:03:39 dhclient: New Routers (em1_vlan1001): <GW> >Oct 19 09:03:39 dhclient: Adding new routes to interface: em1_vlan1001 >Oct 19 09:03:39 dhclient: /sbin/route add default <GW> >Oct 19 09:03:39 dhclient: Creating resolv.conf >Oct 19 09:15:59 dnsmasq[41848]: read /etc/hosts - 21 addresses >Oct 19 09:18:16 dnsmasq[41848]: read /etc/hosts - 21 addresses >Oct 19 09:28:45 dnsmasq[41848]: read /etc/hosts - 20 addresses >Oct 19 09:33:46 dhclient: RENEW >Oct 19 10:03:53 dhclient: RENEW > >Notice DynDns did NOT run. >Midnight rolls around, and NOW the script runs (from cron): > >Oct 20 00:39:17 dhclient: RENEW >Oct 20 01:01:00 php: : DynDns: updatedns() starting >Oct 20 01:01:00 php: : DynDns debug information: <IP_OLD> extracted >from local system. >Oct 20 01:01:00 php: : DynDns: Current WAN IP: <IP_OLD> Cached IP: ><IP_OLD> >Oct 20 01:01:00 php: : phpDynDNS: No change in my IP address and/or >25 days has not passed. Not updating dynamic DNS entry. >Oct 20 01:09:17 dhclient: RENEW >Oct 20 14:39:21 dhclient: RENEW >Oct 20 15:39:22 dhclient: EXPIRE >Oct 20 15:39:22 dhclient: Deleting old routes >Oct 20 15:39:22 dhclient: PREINIT >Oct 20 15:40:23 dhclient: FAIL >Oct 20 15:41:26 dhclient: FAIL >Oct 20 15:42:27 dhclient: FAIL >Oct 20 16:09:20 dhclient: FAIL >Oct 20 16:09:22 dhclient: ARPSEND >Oct 20 16:09:24 dhclient: ARPCHECK >Oct 20 16:09:26 dhclient: BOUND >Oct 20 16:09:26 dhclient: Starting add_new_address() >Oct 20 16:09:26 dhclient: ifconfig em1_vlan1001 inet <IP_NEW> netmask ><MASK> broadcast <BROADCAST> >Oct 20 16:09:26 dhclient: New IP Address (em1_vlan1001): <IP_NEW> >Oct 20 16:09:26 dhclient: New Subnet Mask (em1_vlan1001): <MASK> >Oct 20 16:09:26 dhclient: New Broadcast Address (em1_vlan1001): ><BROADCAST> >Oct 20 16:09:26 dhclient: New Routers (em1_vlan1001): <GW> >Oct 20 16:09:26 dhclient: Adding new routes to interface: em1_vlan1001 >Oct 20 16:09:27 dhclient: /sbin/route add default <GW> >Oct 20 16:09:27 dhclient: Creating resolv.conf >Oct 20 16:39:26 dhclient: RENEW > >Manually restarted dyndns (edit rule, save ... no changes made): > >Oct 20 16:49:18 php: /index.php: Successful webConfigurator login for >user 'admin' from 10.10.10.10 >Oct 20 16:51:22 check_reload_status: Syncing firewall >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns: updatedns() >starting >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns debug >information: <IP_NEW> extracted from local system. >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns: Current WAN >IP: <IP_NEW> Cached IP: <IP_OLD> >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns debug >information: DynDns: cacheIP != wan_ip. Updating. Cached IP: <IP_OLD> >WAN IP: <IP_NEW> >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns: DynDns >_update() starting. >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns: DynDns >_checkStatus() starting. >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns: Current >Service: dyndns >Oct 20 16:51:22 php: /services_dyndns_edit.php: DynDns debug >information: <IP_NEW> extracted from local system. >Oct 20 16:51:22 php: /services_dyndns_edit.php: phpDynDNS: updating >cache file /conf/dyndns_wandyndns'uxorious.dyndns.org'.cache: <IP_NEW> >Oct 20 16:51:22 php: /services_dyndns_edit.php: phpDynDNS: (Success) >IP Address Changed Successfully! (<IP_NEW>) > >Something is going on! > >Regards, >-Jeppe >_______________________________________________ >List mailing list >[email protected] >http://lists.pfsense.org/mailman/listinfo/list _______________________________________________ List mailing list [email protected] http://lists.pfsense.org/mailman/listinfo/list
