Long delay during boot



  • I had issues with the snapshot from 8th (built on Sat Nov 08 15:38:47 CST 2014) with packages and long reboot after config restore. When the box finally booted, it had menu items for packages, but no actual packages installed. Checking Packages -> Installed showed no packages installed.

    Bootup also got stuck on "Configuring Firewall." for ~7 minutes. Initially when upgrading from ~27th Sep to 8th Nov I was patient enough to wait for about 5 minutes before I did a reinstall of a snapshot from 23th Sep that I had ready on a USB stick -> upgrade -> Restore and again it took ages to boot up.

    Here's the system.log from my last boot.

    
    Nov  9 17:17:01 pfsense syslogd: kernel boot file is /boot/kernel/kernel
    Nov  9 17:17:01 pfsense kernel: pflog0: promiscuous mode disabled
    Nov  9 17:17:01 pfsense kernel: Waiting (max 60 seconds) for system process `vnlru' to stop...done
    Nov  9 17:17:01 pfsense kernel: Waiting (max 60 seconds) for system process `bufdaemon' to stop...done
    Nov  9 17:17:01 pfsense kernel: Waiting (max 60 seconds) for system process `syncer' to stop...
    Nov  9 17:17:01 pfsense kernel: Syncing disks, vnodes remaining...0 0 done
    Nov  9 17:17:01 pfsense kernel: All buffers synced.
    Nov  9 17:17:01 pfsense kernel: Copyright (c) 1992-2014 The FreeBSD Project.
    Nov  9 17:17:01 pfsense kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
    Nov  9 17:17:01 pfsense kernel: The Regents of the University of California. All rights reserved.
    Nov  9 17:17:01 pfsense kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
    Nov  9 17:17:01 pfsense kernel: FreeBSD 10.1-RC4-p1 #0 a7c1e8b(releng/10.1)-dirty: Sat Nov  8 16:19:59 CST 2014
    Nov  9 17:17:01 pfsense kernel: root@pfsense-22-amd64-builder:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10 amd64
    Nov  9 17:17:01 pfsense kernel: FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
    Nov  9 17:17:01 pfsense kernel: CPU: Intel(R) Pentium(R) CPU G630T @ 2.30GHz (2294.84-MHz K8-class CPU)
    Nov  9 17:17:01 pfsense kernel: Origin = "GenuineIntel"  Id = 0x206a7  Family = 0x6  Model = 0x2a  Stepping = 7
    Nov  9 17:17:01 pfsense kernel: Features=0xbfebfbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,htt,tm,pbe>Nov  9 17:17:01 pfsense kernel: Features2=0xd9ae3bf <sse3,pclmulqdq,dtes64,mon,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4.1,sse4.2,popcnt,tscdlt,xsave,osxsave>Nov  9 17:17:01 pfsense kernel: AMD Features=0x28100800 <syscall,nx,rdtscp,lm>Nov  9 17:17:01 pfsense kernel: AMD Features2=0x1 <lahf>Nov  9 17:17:01 pfsense kernel: VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID
    Nov  9 17:17:01 pfsense kernel: TSC: P-state invariant, performance statistics
    Nov  9 17:17:01 pfsense kernel: real memory  = 8589934592 (8192 MB)
    Nov  9 17:17:01 pfsense kernel: avail memory = 8185839616 (7806 MB)
    Nov  9 17:17:01 pfsense kernel: Event timer "LAPIC" quality 600
    Nov  9 17:17:01 pfsense kernel: ACPI APIC Table: <intel  s1200kp="">Nov  9 17:17:01 pfsense kernel: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
    Nov  9 17:17:01 pfsense kernel: FreeBSD/SMP: 1 package(s) x 2 core(s)
    Nov  9 17:17:01 pfsense kernel: cpu0 (BSP): APIC ID:  0
    Nov  9 17:17:01 pfsense kernel: cpu1 (AP): APIC ID:  2
    Nov  9 17:17:01 pfsense kernel: ioapic0 <version 2.0="">irqs 0-23 on motherboard
    Nov  9 17:17:01 pfsense kernel: wlan: mac acl policy registered
    Nov  9 17:17:01 pfsense kernel: iwi_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Nov  9 17:17:01 pfsense kernel: iwi_bss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Nov  9 17:17:01 pfsense kernel: module_register_init: MOD_LOAD (iwi_bss_fw, 0xffffffff8062dd90, 0) error 1
    Nov  9 17:17:01 pfsense kernel: iwi_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Nov  9 17:17:01 pfsense kernel: iwi_ibss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Nov  9 17:17:01 pfsense kernel: module_register_init: MOD_LOAD (iwi_ibss_fw, 0xffffffff8062de40, 0) error 1
    Nov  9 17:17:01 pfsense kernel: iwi_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Nov  9 17:17:01 pfsense kernel: iwi_monitor: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Nov  9 17:17:01 pfsense kernel: module_register_init: MOD_LOAD (iwi_monitor_fw, 0xffffffff8062def0, 0) error 1
    Nov  9 17:17:01 pfsense kernel: random: <software, yarrow="">initialized
    Nov  9 17:17:01 pfsense kernel: kbd1 at kbdmux0
    Nov  9 17:17:01 pfsense kernel: cryptosoft0: <software crypto="">on motherboard
    Nov  9 17:17:01 pfsense kernel: padlock0: No ACE support.
    Nov  9 17:17:01 pfsense kernel: acpi0: <intel s1200kp="">on motherboard
    Nov  9 17:17:01 pfsense kernel: acpi0: Power Button (fixed)
    Nov  9 17:17:01 pfsense kernel: cpu0: <acpi cpu="">on acpi0
    Nov  9 17:17:01 pfsense kernel: cpu1: <acpi cpu="">on acpi0
    Nov  9 17:17:01 pfsense kernel: attimer0: <at timer="">port 0x40-0x43 irq 0 on acpi0
    Nov  9 17:17:01 pfsense kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
    Nov  9 17:17:01 pfsense kernel: Event timer "i8254" frequency 1193182 Hz quality 100
    Nov  9 17:17:01 pfsense kernel: atrtc0: <at realtime="" clock="">port 0x70-0x71 irq 8 on acpi0
    Nov  9 17:17:01 pfsense kernel: Event timer "RTC" frequency 32768 Hz quality 0
    Nov  9 17:17:01 pfsense kernel: hpet0: <high precision="" event="" timer="">iomem 0xfed00000-0xfed003ff on acpi0
    Nov  9 17:17:01 pfsense kernel: Timecounter "HPET" frequency 14318180 Hz quality 950
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET" frequency 14318180 Hz quality 550
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET1" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET2" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET3" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET4" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET5" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Event timer "HPET6" frequency 14318180 Hz quality 440
    Nov  9 17:17:01 pfsense kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
    Nov  9 17:17:01 pfsense kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
    Nov  9 17:17:01 pfsense kernel: pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0
    Nov  9 17:17:01 pfsense kernel: pci0: <acpi pci="" bus="">on pcib0
    Nov  9 17:17:01 pfsense kernel: vgapci0: <vga-compatible display="">port 0xf000-0xf03f mem 0xfe000000-0xfe3fffff,0xe0000000-0xefffffff irq 16 at device 2.0 on pci0
    Nov  9 17:17:01 pfsense kernel: agp0: <sandybridge desktop="" gt1="" ig="">on vgapci0
    Nov  9 17:17:01 pfsense kernel: agp0: aperture size is 256M, detected 65532k stolen memory
    Nov  9 17:17:01 pfsense kernel: vgapci0: Boot video device
    Nov  9 17:17:01 pfsense kernel: pci0: <simple comms="">at device 22.0 (no driver attached)
    Nov  9 17:17:01 pfsense kernel: em0: <intel(r) 1000="" pro="" network="" connection="" 7.4.2="">port 0xf080-0xf09f mem 0xfe500000-0xfe51ffff,0xfe524000-0xfe524fff irq 20 at device 25.0 on pci0
    Nov  9 17:17:01 pfsense kernel: em0: Using an MSI interrupt
    Nov  9 17:17:01 pfsense kernel: ehci0: <ehci (generic)="" usb="" 2.0="" controller="">mem 0xfe523000-0xfe5233ff irq 16 at device 26.0 on pci0
    Nov  9 17:17:01 pfsense kernel: usbus0: EHCI version 1.0
    Nov  9 17:17:01 pfsense kernel: usbus0 on ehci0
    Nov  9 17:17:01 pfsense kernel: pcib1: <acpi pci-pci="" bridge="">irq 17 at device 28.0 on pci0
    Nov  9 17:17:01 pfsense kernel: pci1: <acpi pci="" bus="">on pcib1
    Nov  9 17:17:01 pfsense kernel: pcib2: <acpi pci-pci="" bridge="">irq 16 at device 28.1 on pci0
    Nov  9 17:17:01 pfsense kernel: pci2: <acpi pci="" bus="">on pcib2
    Nov  9 17:17:01 pfsense kernel: em1: <intel(r) 1000="" pro="" network="" connection="" 7.4.2="">port 0xe000-0xe01f mem 0xfe400000-0xfe41ffff,0xfe420000-0xfe423fff irq 17 at device 0.0 on pci2
    Nov  9 17:17:01 pfsense kernel: em1: Using MSIX interrupts with 3 vectors
    Nov  9 17:17:01 pfsense kernel: ehci1: <ehci (generic)="" usb="" 2.0="" controller="">mem 0xfe522000-0xfe5223ff irq 23 at device 29.0 on pci0
    Nov  9 17:17:01 pfsense kernel: usbus1: EHCI version 1.0
    Nov  9 17:17:01 pfsense kernel: usbus1 on ehci1
    Nov  9 17:17:01 pfsense kernel: pcib3: <acpi pci-pci="" bridge="">at device 30.0 on pci0
    Nov  9 17:17:01 pfsense kernel: pci3: <acpi pci="" bus="">on pcib3
    Nov  9 17:17:01 pfsense kernel: isab0: <pci-isa bridge="">at device 31.0 on pci0
    Nov  9 17:17:01 pfsense kernel: isa0: <isa bus="">on isab0
    Nov  9 17:17:01 pfsense kernel: ahci0: <intel cougar="" point="" ahci="" sata="" controller="">port 0xf0d0-0xf0d7,0xf0c0-0xf0c3,0xf0b0-0xf0b7,0xf0a0-0xf0a3,0xf060-0xf07f mem 0xfe521000-0xfe5217ff irq 19 at device 31.2 on pci0
    Nov  9 17:17:01 pfsense kernel: ahci0: AHCI v1.30 with 6 6Gbps ports, Port Multiplier not supported
    Nov  9 17:17:01 pfsense kernel: ahcich0: <ahci channel="">at channel 0 on ahci0
    Nov  9 17:17:01 pfsense kernel: ahcich1: <ahci channel="">at channel 1 on ahci0
    Nov  9 17:17:01 pfsense kernel: ahcich2: <ahci channel="">at channel 2 on ahci0
    Nov  9 17:17:01 pfsense kernel: ahcich3: <ahci channel="">at channel 3 on ahci0
    Nov  9 17:17:01 pfsense kernel: ahciem0: <ahci enclosure="" management="" bridge="">on ahci0
    Nov  9 17:17:01 pfsense kernel: acpi_button0: <power button="">on acpi0
    Nov  9 17:17:01 pfsense kernel: sc0: <system console="">at flags 0x100 on isa0
    Nov  9 17:17:01 pfsense kernel: sc0: VGA <16 virtual consoles, flags=0x300>
    Nov  9 17:17:01 pfsense kernel: vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
    Nov  9 17:17:01 pfsense kernel: atkbdc0: <keyboard controller="" (i8042)="">at port 0x60,0x64 on isa0
    Nov  9 17:17:01 pfsense kernel: atkbd0: <at keyboard="">irq 1 on atkbdc0
    Nov  9 17:17:01 pfsense kernel: kbd0 at atkbd0
    Nov  9 17:17:01 pfsense kernel: atkbd0: [GIANT-LOCKED]
    Nov  9 17:17:01 pfsense kernel: ppc0: cannot reserve I/O port range
    Nov  9 17:17:01 pfsense kernel: est0: <enhanced speedstep="" frequency="" control="">on cpu0
    Nov  9 17:17:01 pfsense kernel: est1: <enhanced speedstep="" frequency="" control="">on cpu1
    Nov  9 17:17:01 pfsense kernel: Timecounters tick every 1.000 msec
    Nov  9 17:17:01 pfsense kernel: IPsec: Initialized Security Association Processing.
    Nov  9 17:17:01 pfsense kernel: random: unblocking device.
    Nov  9 17:17:01 pfsense kernel: usbus0: 480Mbps High Speed USB v2.0
    Nov  9 17:17:01 pfsense kernel: usbus1: 480Mbps High Speed USB v2.0
    Nov  9 17:17:01 pfsense kernel: ugen1.1: <intel>at usbus1
    Nov  9 17:17:01 pfsense kernel: uhub0: <intel 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus1
    Nov  9 17:17:01 pfsense kernel: ugen0.1: <intel>at usbus0
    Nov  9 17:17:01 pfsense kernel: uhub1: <intel 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus0
    Nov  9 17:17:01 pfsense kernel: uhub0: 2 ports with 2 removable, self powered
    Nov  9 17:17:01 pfsense kernel: uhub1: 2 ports with 2 removable, self powered
    Nov  9 17:17:01 pfsense kernel: ugen1.2: <vendor 0x8087="">at usbus1
    Nov  9 17:17:01 pfsense kernel: uhub2: <vendor 2="" 9="" 0x8087="" product="" 0x0024,="" class="" 0,="" rev="" 2.00="" 0.00,="" addr="">on usbus1
    Nov  9 17:17:01 pfsense kernel: ugen0.2: <vendor 0x8087="">at usbus0
    Nov  9 17:17:01 pfsense kernel: uhub3: <vendor 2="" 9="" 0x8087="" product="" 0x0024,="" class="" 0,="" rev="" 2.00="" 0.00,="" addr="">on usbus0
    Nov  9 17:17:01 pfsense kernel: uhub3: 6 ports with 6 removable, self powered
    Nov  9 17:17:01 pfsense kernel: uhub2: 8 ports with 8 removable, self powered
    Nov  9 17:17:01 pfsense kernel: ugen1.3: <vendor 0x04d9="">at usbus1
    Nov  9 17:17:01 pfsense kernel: ukbd0: <vendor 0="" 3="" 0x04d9="" usb="" keyboard,="" class="" 0,="" rev="" 1.10="" 3.10,="" addr="">on usbus1
    Nov  9 17:17:01 pfsense kernel: kbd2 at ukbd0
    Nov  9 17:17:01 pfsense kernel: uhid0: <vendor 0="" 3="" 0x04d9="" usb="" keyboard,="" class="" 0,="" rev="" 1.10="" 3.10,="" addr="">on usbus1
    Nov  9 17:17:01 pfsense kernel: ses0 at ahciem0 bus 0 scbus4 target 0 lun 0
    Nov  9 17:17:01 pfsense kernel: ses0: <ahci sgpio="" enclosure="" 1.00="" 0001="">SEMB S-E-S 2.00 device
    Nov  9 17:17:01 pfsense kernel: ses0: SEMB SES Device
    Nov  9 17:17:01 pfsense kernel: ada0 at ahcich0 bus 0 scbus0 target 0 lun 0
    Nov  9 17:17:01 pfsense kernel: ada0: <kingston sv300s37a60g="" 505abbf0="">ATA-8 SATA 3.x device
    Nov  9 17:17:01 pfsense kernel: ada0: Serial Number 50026B72310717D4
    Nov  9 17:17:01 pfsense kernel: ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
    Nov  9 17:17:01 pfsense kernel: ada0: Command Queueing enabled
    Nov  9 17:17:01 pfsense kernel: ada0: 57241MB (117231408 512 byte sectors: 16H 63S/T 16383C)
    Nov  9 17:17:01 pfsense kernel: ada0: Previously was known as ad4
    Nov  9 17:17:01 pfsense kernel: SMP: AP CPU #1 Launched!
    Nov  9 17:17:01 pfsense kernel: Timecounter "TSC-low" frequency 1147421898 Hz quality 1000
    Nov  9 17:17:01 pfsense kernel: Trying to mount root from ufs:/dev/ada0s1a [rw]...
    Nov  9 17:17:01 pfsense kernel: coretemp0: <cpu on-die="" thermal="" sensors="">on cpu0
    Nov  9 17:17:01 pfsense kernel: coretemp1: <cpu on-die="" thermal="" sensors="">on cpu1
    Nov  9 17:17:02 pfsense sshd[8870]: Server listening on :: port 22.
    Nov  9 17:17:02 pfsense sshd[8870]: Server listening on 0.0.0.0 port 22.
    Nov  9 17:17:02 pfsense sshlockout[9141]: sshlockout/webConfigurator v3.0 starting up
    Nov  9 17:17:03 pfsense kernel: 
    Nov  9 17:17:03 pfsense kernel: em0: link state changed to UP
    Nov  9 17:17:03 pfsense devd: Executing '/usr/local/sbin/pfSctl -c 'interface linkup start em0''
    Nov  9 17:17:03 pfsense check_reload_status: Linkup starting em0
    Nov  9 17:17:08 pfsense check_reload_status: rc.newwanip starting em0
    Nov  9 17:17:09 pfsense php: rc.bootup: Resyncing OpenVPN instances.
    Nov  9 17:17:09 pfsense kernel: done.
    Nov  9 17:17:09 pfsense dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Nov  9 17:17:09 pfsense kernel: 
    Nov  9 17:17:09 pfsense kernel: tun1: changing name to 'ovpns1'
    Nov  9 17:17:09 pfsense kernel: tun2: changing name to 'ovpns2'
    Nov  9 17:17:09 pfsense kernel: ovpns1: link state changed to UP
    Nov  9 17:17:09 pfsense check_reload_status: rc.newwanip starting ovpns1
    Nov  9 17:17:09 pfsense kernel: pflog0: promiscuous mode enabled
    Nov  9 17:17:09 pfsense kernel: ovpns2: link state changed to UP
    Nov  9 17:17:09 pfsense check_reload_status: rc.newwanip starting ovpns2
    Nov  9 17:17:10 pfsense php-fpm[284]: /rc.newwanip: rc.newwanip: Info: starting on em0.
    Nov  9 17:17:10 pfsense php-fpm[284]: /rc.newwanip: rc.newwanip: on (IP address: 84.MY.WAN.IP) (interface: WAN[wan]) (real interface: em0).
    Nov  9 17:17:10 pfsense php-fpm[284]: /rc.newwanip: IP has changed, killing states on former IP 0.0.0.0.
    Nov  9 17:17:10 pfsense dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Nov  9 17:17:10 pfsense php-fpm[284]: /rc.newwanip: ROUTING: setting default route to 84.DDD.NN.1
    Nov  9 17:17:10 pfsense php-fpm[284]: /rc.newwanip: RRD create failed exited with 1, the error is: ERROR: creating '/var/db/rrd/WAN_DHCP-quality.rrd': No such file or directory
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: rc.newwanip: on (IP address: 192.OPEN.VPN.IP2) (interface: []) (real interface: ovpns1).
    Nov  9 17:17:10 pfsense check_reload_status: Reloading filter
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.OPEN.VPN.IP2 - Restarting packages.
    Nov  9 17:17:10 pfsense check_reload_status: Starting packages
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2.
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: rc.newwanip: on (IP address: 192.OPEN.VPN.IP1) (interface: []) (real interface: ovpns2).
    Nov  9 17:17:10 pfsense check_reload_status: Reloading filter
    Nov  9 17:17:10 pfsense php-fpm[25534]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.OPEN.VPN.IP1 - Restarting packages.
    Nov  9 17:17:10 pfsense check_reload_status: Starting packages
    Nov  9 17:17:12 pfsense php-fpm[284]: /rc.newwanip: phpDynDNS (my.dyn.dns.com): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
    Nov  9 17:17:13 pfsense php-fpm[29425]: /rc.start_packages: Restarting/Starting all packages.
    Nov  9 17:17:13 pfsense php-fpm[29425]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[29425]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[29425]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[29425]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[284]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    Nov  9 17:17:13 pfsense SnortStartup[34548]: Snort START for SnortLAN(330_em1)...
    Nov  9 17:17:13 pfsense kernel: ovpns1: link state changed to DOWN
    Nov  9 17:17:13 pfsense check_reload_status: Reloading filter
    Nov  9 17:17:13 pfsense snort[34589]: FATAL ERROR: OpenAlertFile() => fopen() alert file /var/log/snort/snort_em1330/alert: No such file or directory
    Nov  9 17:17:13 pfsense kernel: ovpns2: link state changed to DOWN
    Nov  9 17:17:13 pfsense kernel: ovpns1: link state changed to UP
    Nov  9 17:17:13 pfsense check_reload_status: rc.newwanip starting ovpns1
    Nov  9 17:17:13 pfsense php-fpm[284]: /rc.newwanip: Creating rrd update script
    Nov  9 17:17:13 pfsense kernel: ovpns2: link state changed to UP
    Nov  9 17:17:13 pfsense check_reload_status: rc.newwanip starting ovpns2
    Nov  9 17:17:13 pfsense php-fpm[55608]: /rc.start_packages: Restarting/Starting all packages.
    Nov  9 17:17:13 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:13 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:14 pfsense SnortStartup[59780]: Snort START for SnortLAN(330_em1)...
    Nov  9 17:17:14 pfsense snort[59812]: FATAL ERROR: OpenAlertFile() => fopen() alert file /var/log/snort/snort_em1330/alert: No such file or directory
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: rc.newwanip: on (IP address: 192.OPEN.VPN.IP2) (interface: []) (real interface: ovpns1).
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.OPEN.VPN.IP2 - Restarting packages.
    Nov  9 17:17:14 pfsense check_reload_status: Starting packages
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2.
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: rc.newwanip: on (IP address: 192.OPEN.VPN.IP1) (interface: []) (real interface: ovpns2).
    Nov  9 17:17:14 pfsense php-fpm[55608]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.OPEN.VPN.IP1 - Restarting packages.
    Nov  9 17:17:14 pfsense check_reload_status: Starting packages
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: Restarting/Starting all packages.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense SnortStartup[82584]: Snort START for SnortLAN(330_em1)...
    Nov  9 17:17:15 pfsense snort[82877]: FATAL ERROR: OpenAlertFile() => fopen() alert file /var/log/snort/snort_em1330/alert: No such file or directory
    Nov  9 17:17:15 pfsense php-fpm[284]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 0.0.0.0 ->  84.MY.WAN.IP - Restarting packages.
    Nov  9 17:17:15 pfsense check_reload_status: Starting packages
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: Restarting/Starting all packages.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense php-fpm[55608]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:17:15 pfsense SnortStartup[97882]: Snort START for SnortLAN(330_em1)...
    Nov  9 17:17:15 pfsense snort[98213]: FATAL ERROR: OpenAlertFile() => fopen() alert file /var/log/snort/snort_em1330/alert: No such file or directory
    Nov  9 17:17:16 pfsense kernel: em1: link state changed to UP
    Nov  9 17:17:16 pfsense devd: Executing '/usr/local/sbin/pfSctl -c 'interface linkup start em1''
    Nov  9 17:17:16 pfsense check_reload_status: Linkup starting em1
    Nov  9 17:24:09 pfsense kernel: ...
    Nov  9 17:24:09 pfsense kernel: .done.
    Nov  9 17:24:09 pfsense php: rc.bootup: The command '/usr/sbin/pw groupadd  -g  -M 2000 2>&1' returned exit code '65', the output was 'pw: group name required' 
    Nov  9 17:24:09 pfsense kernel: done.
    Nov  9 17:24:10 pfsense php: rc.bootup: ROUTING: setting default route to 84.DDD.NN.1
    Nov  9 17:24:10 pfsense kernel: done.
    Nov  9 17:24:10 pfsense dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Nov  9 17:24:10 pfsense kernel: done.
    Nov  9 17:24:10 pfsense dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Nov  9 17:24:10 pfsense dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Nov  9 17:24:10 pfsense dhcpleases: kqueue error: unkown
    Nov  9 17:24:10 pfsense kernel: done.
    Nov  9 17:24:10 pfsense check_reload_status: Updating all dyndns
    Nov  9 17:24:11 pfsense php-fpm[55608]: /rc.dyndns.update: phpDynDNS (my.dyn.dns.com): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
    Nov  9 17:24:13 pfsense kernel: ..
    Nov  9 17:24:14 pfsense kernel: ..
    Nov  9 17:24:14 pfsense kernel: .done.
    Nov  9 17:24:19 pfsense php: rc.bootup: Creating rrd update script
    Nov  9 17:24:19 pfsense php: rc.bootup: miniupnpd: Starting service on interface: lan
    Nov  9 17:24:19 pfsense kernel: done.
    Nov  9 17:24:19 pfsense kernel: done.
    Nov  9 17:24:19 pfsense php-fpm[71347]: /rc.start_packages: Restarting/Starting all packages.
    Nov  9 17:24:19 pfsense php-fpm[71347]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:24:19 pfsense php-fpm[71347]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:24:19 pfsense php-fpm[71347]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:24:19 pfsense php-fpm[71347]: /rc.start_packages: No pfBlocker action during boot process.
    Nov  9 17:24:19 pfsense SnortStartup[3452]: Snort START for SnortLAN(330_em1)...
    Nov  9 17:24:19 pfsense snort[4339]: FATAL ERROR: OpenAlertFile() => fopen() alert file /var/log/snort/snort_em1330/alert: No such file or directory
    Nov  9 17:24:20 pfsense login: login on ttyv0 as root
    Nov  9 17:24:20 pfsense sshlockout[21384]: sshlockout/webConfigurator v3.0 starting up
    Nov  9 17:24:32 pfsense php-fpm[71347]: /index.php: Successful login for user 'admin' from: 192.168.XX.YY
    Nov  9 17:24:32 pfsense php-fpm[71347]: /index.php: Successful login for user 'admin' from: 192.168.XX.YY
    Nov  9 17:25:51 pfsense sshd[45878]: Accepted keyboard-interactive/pam for root from 192.168.XX.YY port 63416 ssh2</cpu></cpu></kingston></ahci></vendor></vendor></vendor></vendor></vendor></vendor></vendor></intel></intel></intel></intel></enhanced></enhanced></at></keyboard></generic></system></power></ahci></ahci></ahci></ahci></ahci></intel></isa></pci-isa></acpi></acpi></ehci></intel(r)></acpi></acpi></acpi></acpi></ehci></intel(r)></simple></sandybridge></vga-compatible></acpi></acpi></high></at></at></acpi></acpi></intel></software></software,></version></intel ></lahf></syscall,nx,rdtscp,lm></sse3,pclmulqdq,dtes64,mon,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4.1,sse4.2,popcnt,tscdlt,xsave,osxsave></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,htt,tm,pbe> 
    


  • Split this off to its own thread since it has nothing to do with the thread you posted in, please don't hijack unrelated threads.

    Are you using hostnames in aliases, IPsec, or anywhere else? DNS delays seem most suspect, but hard to say from that.



  • @cmb:

    Are you using hostnames in aliases, IPsec, or anywhere else? DNS delays seem most suspect, but hard to say from that.

    I'm only using IP/port aliases and pfBlocker. Other packages / features I have enabled are Snort and OpenVPN.

    I just updated to the 10th Nov snapshot and it took about 7-9 minutes for the firewall to get online again.

    I went through my config.xml and couldn't find anything odd about it. Is there any further information I can provide?

    Edit: Another reboot with 10th Nov (built on Mon Nov 10 02:26:14 CST 2014) snapshot and no delay. Reboot time was less than 2 minutes.



  • I don't see anything obvious that'd cause a boot delay along those lines. Something took a long time in the linkup of the NIC, and it's not clear what from that.

    Is it only reboots post-upgrade?


  • Moderator

    There was an issue with pfctl which I think Ermal pushed a fix for awhile back (see Bug # 3854 on Redmine.)

    At that time, from the pfSense Terminal, it was stuck on "Loading Network" or something like that for about 3-5mins.

    Its faster now, but I still notice that 2.2 (Bare Metal and VM) takes a bit longer to load than any of my 2.1.5 boxes.



  • @cmb:

    I don't see anything obvious that'd cause a boot delay along those lines. Something took a long time in the linkup of the NIC, and it's not clear what from that.

    Is it only reboots post-upgrade?

    With the Sunday snapshot I was able to replicate the same delay multiple times with no changes made before reboot. It seems to be a lot better with the current snapshot with sub 2 minute reboot time for the last 2 times I've tested.


Log in to reply