Startup hangs intermittently
-
This example is using a 2.1-DEVELOPMENT 2G nanobsd snapshot from 7 March on ALIX 2D13. But I also get similar things on my production 2.0.1 ALIX systems. In my environment (remote locations in Nepal) the power goes off unexpectedly quite often, and our UPS systems are not perfect! So we often just have our routers powered off without a software shutdown. For nanobsd, I don't think this should be an issue, since the real files and config used at boot are mounted RO anyway. All the /tmp and /var stuff gets created from scratch at boot time in RAM.
Quite often, when we powerup, the front LEDs start doing their flashing after about 1 minute (i.e. after the inital BIOS and FreeBSD startup gets to the pfSense bit). But then the flashing goes on for a long time/more than 30 minutes/forever. I did have an example yesterday when there was a pause of 6 minutes between "Starting syslog…done." and "Configuring firewall..." During this time the LED flashing stopped. So sometimes something delays the startup, but then it gets going again and finishes.
Yesterday I had this happen on a test system where I was watching the console. I never got the "Configuring firewall..." message - console output stopped after "Starting syslog...done.".
This system (and all my systems) have pfBlocker, Squid and SquidGuard packages. As it happens, pfBlocker was installed but not enabled on this system.
I could logon to the router with SSH and (re)start the webGUI. So I have captured some data:
system.log
Mar 13 11:03:07 davis21dev syslogd: kernel boot file is /boot/kernel/kernel Mar 13 11:03:07 davis21dev kernel: Copyright (c) 1992-2012 The FreeBSD Project. Mar 13 11:03:07 davis21dev kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 Mar 13 11:03:07 davis21dev kernel: The Regents of the University of California. All rights reserved. Mar 13 11:03:07 davis21dev kernel: FreeBSD is a registered trademark of The FreeBSD Foundation. Mar 13 11:03:07 davis21dev kernel: FreeBSD 8.3-RC1 #3: Wed Mar 7 22:27:59 CET 2012 Mar 13 11:03:07 davis21dev kernel: root@b83i386.dnsalias.org:/usr/obj.pfSense/usr/pfSensesrc/src/sys/pfSense_wrap.8.i386 i386 Mar 13 11:03:07 davis21dev kernel: Timecounter "i8254" frequency 1193182 Hz quality 0 Mar 13 11:03:07 davis21dev kernel: CPU: Geode(TM) Integrated Processor by AMD PCS (498.05-MHz 586-class CPU) Mar 13 11:03:07 davis21dev kernel: Origin = "AuthenticAMD" Id = 0x5a2 Family = 5 Model = a Stepping = 2 Mar 13 11:03:07 davis21dev kernel: Features=0x88a93d <fpu,de,pse,tsc,msr,cx8,sep,pge,cmov,clflush,mmx>Mar 13 11:03:07 davis21dev kernel: AMD Features=0xc0400000 <mmx+,3dnow!+,3dnow!>Mar 13 11:03:07 davis21dev kernel: real memory = 268435456 (256 MB) Mar 13 11:03:07 davis21dev kernel: avail memory = 239239168 (228 MB) Mar 13 11:03:07 davis21dev kernel: pnpbios: Bad PnP BIOS data checksum Mar 13 11:03:07 davis21dev kernel: netisr_init: forcing maxthreads to 1 and bindthreads to 0 for device polling Mar 13 11:03:07 davis21dev kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Mar 13 11:03:07 davis21dev kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xc0720ce0, 0) error 1 Mar 13 11:03:07 davis21dev kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Mar 13 11:03:07 davis21dev kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xc0720d80, 0) error 1 Mar 13 11:03:07 davis21dev kernel: wlan: mac acl policy registered Mar 13 11:03:07 davis21dev kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Mar 13 11:03:07 davis21dev kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xc0720c40, 0) error 1 Mar 13 11:03:07 davis21dev kernel: K6-family MTRR support enabled (2 registers) Mar 13 11:03:07 davis21dev kernel: ACPI Error: A valid RSDP was not found (20101013/tbxfroot-309) Mar 13 11:03:07 davis21dev kernel: ACPI: Table initialisation failed: AE_NOT_FOUND Mar 13 11:03:07 davis21dev kernel: ACPI: Try disabling either ACPI or apic support. Mar 13 11:03:07 davis21dev kernel: cryptosoft0: <software crypto="">on motherboard Mar 13 11:03:07 davis21dev kernel: padlock0: No ACE support. Mar 13 11:03:07 davis21dev kernel: pcib0: <host to="" pci="" bridge="">pcibus 0 on motherboard Mar 13 11:03:07 davis21dev kernel: pci0: <pci bus="">on pcib0 Mar 13 11:03:07 davis21dev kernel: Geode LX: PC Engines ALIX.2 v0.99h tinyBIOS V1.4a (C)1997-2007 Mar 13 11:03:07 davis21dev kernel: pci0: <encrypt decrypt,="" entertainment="" crypto="">at device 1.2 (no driver attached) Mar 13 11:03:07 davis21dev kernel: vr0: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1000-0x10ff mem 0xe0000000-0xe00000ff irq 10 at device 9.0 on pci0 Mar 13 11:03:07 davis21dev kernel: vr0: Quirks: 0x2 Mar 13 11:03:07 davis21dev kernel: vr0: Revision: 0x96 Mar 13 11:03:07 davis21dev kernel: miibus0: <mii bus="">on vr0 Mar 13 11:03:07 davis21dev kernel: ukphy0: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus0 Mar 13 11:03:07 davis21dev kernel: ukphy0: none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow Mar 13 11:03:07 davis21dev kernel: vr0: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: vr1: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1400-0x14ff mem 0xe0040000-0xe00400ff irq 11 at device 10.0 on pci0 Mar 13 11:03:07 davis21dev kernel: vr1: Quirks: 0x2 Mar 13 11:03:07 davis21dev kernel: vr1: Revision: 0x96 Mar 13 11:03:07 davis21dev kernel: miibus1: <mii bus="">on vr1 Mar 13 11:03:07 davis21dev kernel: ukphy1: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus1 Mar 13 11:03:07 davis21dev kernel: ukphy1: none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow Mar 13 11:03:07 davis21dev kernel: vr1: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: vr2: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1800-0x18ff mem 0xe0080000-0xe00800ff irq 15 at device 11.0 on pci0 Mar 13 11:03:07 davis21dev kernel: vr2: Quirks: 0x2 Mar 13 11:03:07 davis21dev kernel: vr2: Revision: 0x96 Mar 13 11:03:07 davis21dev kernel: miibus2: <mii bus="">on vr2 Mar 13 11:03:07 davis21dev kernel: ukphy2: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus2 Mar 13 11:03:07 davis21dev kernel: ukphy2: none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow Mar 13 11:03:07 davis21dev kernel: vr2: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: isab0: <pci-isa bridge="">port 0x6000-0x6007,0x6100-0x61ff,0x6200-0x623f,0x9d00-0x9d7f,0x9c00-0x9c3f at device 15.0 on pci0 Mar 13 11:03:07 davis21dev kernel: isa0: <isa bus="">on isab0 Mar 13 11:03:07 davis21dev kernel: atapci0: <amd cs5536="" udma100="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xff00-0xff0f at device 15.2 on pci0 Mar 13 11:03:07 davis21dev kernel: ata0: <ata channel="">at channel 0 on atapci0 Mar 13 11:03:07 davis21dev kernel: ata0: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: ata1: <ata channel="">at channel 1 on atapci0 Mar 13 11:03:07 davis21dev kernel: ata1: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: ohci0: <ohci (generic)="" usb="" controller="">mem 0xefffe000-0xefffefff irq 12 at device 15.4 on pci0 Mar 13 11:03:07 davis21dev kernel: ohci0: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: usbus0: <ohci (generic)="" usb="" controller="">on ohci0 Mar 13 11:03:07 davis21dev kernel: ehci0: <amd cs5536="" (geode)="" usb="" 2.0="" controller="">mem 0xefffd000-0xefffdfff irq 12 at device 15.5 on pci0 Mar 13 11:03:07 davis21dev kernel: ehci0: [ITHREAD] Mar 13 11:03:07 davis21dev kernel: usbus1: EHCI version 1.0 Mar 13 11:03:07 davis21dev kernel: usbus1: <amd cs5536="" (geode)="" usb="" 2.0="" controller="">on ehci0 Mar 13 11:03:07 davis21dev kernel: cpu0 on motherboard Mar 13 11:03:07 davis21dev kernel: orm0: <isa option="" rom="">at iomem 0xe0000-0xea7ff pnpid ORM0000 on isa0 Mar 13 11:03:07 davis21dev kernel: atrtc0: <at real="" time="" clock="">at port 0x70 irq 8 on isa0 Mar 13 11:03:07 davis21dev kernel: ppc0: parallel port not found. Mar 13 11:03:07 davis21dev kernel: uart0: <16550 or compatible> at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0 Mar 13 11:03:07 davis21dev kernel: uart0: [FILTER] Mar 13 11:03:07 davis21dev kernel: uart0: console (9600,n,8,1) Mar 13 11:03:07 davis21dev kernel: uart1: <16550 or compatible> at port 0x2f8-0x2ff irq 3 on isa0 Mar 13 11:03:07 davis21dev kernel: uart1: [FILTER] Mar 13 11:03:07 davis21dev kernel: Timecounter "TSC" frequency 498052802 Hz quality 800 Mar 13 11:03:07 davis21dev kernel: Timecounters tick every 10.000 msec Mar 13 11:03:07 davis21dev kernel: IPsec: Initialized Security Association Processing. Mar 13 11:03:07 davis21dev kernel: usbus0: 12Mbps Full Speed USB v1.0 Mar 13 11:03:07 davis21dev kernel: usbus1: 480Mbps High Speed USB v2.0 Mar 13 11:03:07 davis21dev kernel: ugen0.1: <amd>at usbus0 Mar 13 11:03:07 davis21dev kernel: uhub0: <amd 1="" 9="" ohci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus0 Mar 13 11:03:07 davis21dev kernel: ugen1.1: <amd>at usbus1 Mar 13 11:03:07 davis21dev kernel: uhub1: <amd 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus1 Mar 13 11:03:07 davis21dev kernel: ad0: 1907MB <sandisk sdcfh-002g="" hdx="" 6.02="">at ata0-master PIO4 Mar 13 11:03:07 davis21dev kernel: Root mount waiting for: usbus1 usbus0 Mar 13 11:03:07 davis21dev kernel: uhub0: 4 ports with 4 removable, self powered Mar 13 11:03:07 davis21dev kernel: Root mount waiting for: usbus1 Mar 13 11:03:07 davis21dev kernel: uhub1: 4 ports with 4 removable, self powered Mar 13 11:03:07 davis21dev kernel: Trying to mount root from ufs:/dev/ufs/pfsense0 Mar 13 11:03:07 davis21dev kernel: WARNING: / was not properly dismounted Mar 13 11:03:07 davis21dev kernel: ad0: FAILURE - SETFEATURES 0x85 status=51 <ready,dsc,error>error=4 <aborted>Mar 13 11:03:09 davis21dev check_reload_status: Linkup starting vr0 Mar 13 11:03:09 davis21dev kernel: vr0: link state changed to UP Mar 13 11:03:13 davis21dev check_reload_status: Syncing firewall Mar 13 11:03:15 davis21dev apinger: Error while feeding rrdtool: Broken pipe Mar 13 11:03:15 davis21dev php: : Starting Squid Mar 13 11:03:15 davis21dev squid[43129]: Squid Parent: child process 43652 started Mar 13 11:03:16 davis21dev check_reload_status: Reloading filter Mar 13 11:03:17 davis21dev check_reload_status: Syncing firewall Mar 13 11:03:18 davis21dev squid[43652]: The url_rewriter helpers are crashing too rapidly, need help! Mar 13 11:03:18 davis21dev squid[43129]: Squid Parent: child process 43652 exited due to signal 6 Mar 13 11:03:18 davis21dev kernel: pid 43652 (squid), uid 62: exited on signal 6 Mar 13 11:03:21 davis21dev squid[43129]: Squid Parent: child process 48603 started Mar 13 11:04:15 davis21dev apinger: /usr/local/bin/rrdtool respawning too fast, waiting 300s. Mar 13 11:10:35 davis21dev sshd[24315]: Accepted keyboard-interactive/pam for admin from 192.168.2.2 port 49567 ssh2 Mar 13 11:10:35 davis21dev sshlockout[32722]: sshlockout/webConfigurator v3.0 starting up Mar 13 12:02:08 davis21dev dhclient: RENEW Mar 13 12:02:08 davis21dev dhclient: Creating resolv.conf Mar 13 12:22:28 davis21dev sshd[49679]: Accepted keyboard-interactive/pam for admin from 192.168.2.2 port 49574 ssh2 Mar 13 12:54:38 davis21dev sshd[24315]: Timeout, client not responding. Mar 13 13:02:09 davis21dev dhclient: RENEW Mar 13 13:02:09 davis21dev dhclient: Creating resolv.conf Mar 13 14:02:09 davis21dev dhclient: RENEW Mar 13 14:02:09 davis21dev dhclient: Creating resolv.conf Mar 13 14:32:09 davis21dev php: : Creating rrd update script Mar 13 14:32:18 davis21dev apinger: Error while feeding rrdtool: Broken pipe Mar 13 14:32:23 davis21dev php: /index.php: Successful login for user 'admin' from: 192.168.2.2 Mar 13 14:32:23 davis21dev php: /index.php: Successful login for user 'admin' from: 192.168.2.2 Mar 13 15:02:14 davis21dev dhclient: RENEW Mar 13 15:02:14 davis21dev dhclient: Creating resolv.conf</aborted></ready,dsc,error></sandisk></amd></amd></amd></amd></at></isa></amd></amd></ohci></ohci></ata></ata></amd></isa></pci-isa></generic></mii></via></generic></mii></via></generic></mii></via></encrypt></pci></host></software></mmx+,3dnow!+,3dnow!></fpu,de,pse,tsc,msr,cx8,sep,pge,cmov,clflush,mmx>ps ax output
PID TT STAT TIME COMMAND 0 ?? DLs 0:00.05 [kernel] 1 ?? ILs 0:00.19 /sbin/init -- 2 ?? DL 0:00.06 [g_event] 3 ?? DL 0:06.05 [g_up] 4 ?? DL 0:08.91 [g_down] 5 ?? DL 0:00.00 [crypto] 6 ?? DL 0:00.00 [crypto returns] 7 ?? DL 0:00.11 [pfpurge] 8 ?? DL 0:00.00 [xpt_thrd] 9 ?? DL 0:01.11 [pagedaemon] 10 ?? RL 224:04.16 [idle] 11 ?? WL 9:29.00 [intr] 12 ?? DL 0:00.00 [ng_queue] 13 ?? DL 0:19.96 [yarrow] 14 ?? DL 0:00.38 [usb] 15 ?? DL 0:00.00 [vmdaemon] 16 ?? DL 0:00.03 [idlepoll] 17 ?? DL 0:00.00 [pagezero] 18 ?? DL 0:00.11 [bufdaemon] 19 ?? DL 0:00.65 [vnlru] 20 ?? DL 0:03.78 [syncer] 21 ?? DL 0:00.10 [softdepflush] 29 ?? DL 0:00.50 [md0] 35 ?? DL 0:01.25 [md1] 268 ?? INs 0:00.02 /usr/local/sbin/check_reload_status 270 ?? IN 0:00.00 check_reload_status: Monitoring daemon of check_reloa 288 ?? Is 0:00.01 /sbin/devd 8161 ?? Is 0:00.01 /usr/sbin/sshd 8699 ?? Is 0:00.02 dhclient: vr1 [priv] (dhclient) 10337 ?? SN 0:00.00 sleep 55 14613 ?? Is 0:00.02 dhclient: vr1 (dhclient) 17350 ?? IN 0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync 17952 ?? SNs 0:04.44 /usr/local/sbin/apinger -c /var/etc/apinger.conf 27465 ?? S 0:00.62 /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfig 27746 ?? Is 0:00.28 /usr/local/bin/php 28394 ?? Is 0:00.28 /usr/local/bin/php 30007 ?? I 0:01.09 /usr/local/bin/php 30351 ?? I 0:00.00 /usr/local/bin/php 30664 ?? I 0:01.86 /usr/local/bin/php 31001 ?? I 0:01.10 /usr/local/bin/php 32722 ?? Is 0:00.02 /usr/local/sbin/sshlockout_pf 15 33598 ?? IN 0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync 34240 ?? SN 0:00.32 /usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0 34399 ?? IN 0:00.00 logger -t pf -p local0.info 38888 ?? Is 0:00.10 /usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f 43049 ?? INs 0:00.01 ntpd: [priv] (ntpd) 43105 ?? SN 0:00.29 ntpd: ntp engine (ntpd) 43129 ?? INs 0:00.00 /usr/pbi/squid-i386/sbin/squid -D -f /usr/local/etc/s 43452 ?? IN 0:00.00 ntpd: dns engine (ntpd) 47869 ?? SN 0:00.70 /bin/sh /usr/local/etc/rc.d/proxy_monitor.sh start 48203 ?? IN 0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync 48603 ?? SN 0:00.84 (squid) -D -f /usr/local/etc/squid/squid.conf (squid) 48694 ?? IN 0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s 48898 ?? IN 0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s 49135 ?? IN 0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s 49519 ?? IN 0:00.00 (unlinkd) (unlinkd) 49679 ?? Ss 0:03.41 sshd: admin@pts/1 (sshd) 49805 ?? IN 0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local 50193 ?? IN 0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local 50201 ?? IN 0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local 50256 ?? IN 0:00.04 /usr/local/bin/rrdtool - 54334 ?? IN 0:01.07 /usr/local/bin/php -f /etc/rc.filter_configure_sync 60322 ?? IN 0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync 62444 ?? Is 0:00.06 /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf 22 u0 Is+ 0:00.07 sh /etc/rc autoboot 273 u0 I+ 0:03.62 /usr/local/bin/php -f /etc/rc.bootup 7674 1 SN 0:00.00 sleep 60 10503 1 R+ 0:00.01 ps ax 17270 1 Is 0:00.03 /bin/sh /etc/rc.initial 29368 1 SN 0:00.69 /bin/sh /var/db/rrd/updaterrd.sh 52567 1 S 0:00.20 /bin/tcshrc processes with their elapsed times:
03:54:58 17350 /usr/local/bin/php -f /etc/rc.filter_configure_sync 03:54:51 33598 /usr/local/bin/php -f /etc/rc.filter_configure_sync 03:54:35 47869 /bin/sh /usr/local/etc/rc.d/proxy_monitor.sh start 03:54:34 48203 /usr/local/bin/php -f /etc/rc.filter_configure_sync 03:55:11 54334 /usr/local/bin/php -f /etc/rc.filter_configure_sync 03:55:05 60322 /usr/local/bin/php -f /etc/rc.filter_configure_sync 03:56:23 22 sh /etc/rc autoboot 03:56:03 273 /usr/local/bin/php -f /etc/rc.bootup 02:35:27 17270 /bin/sh /etc/rc.initialBoth /tmp/config.lock and /tmp/filter.lock existed. By running other scripts that needed these locks, I could determine that the config lock was available, but that something was holding the filter lock. You will notice that after autoboot and rc.bootup, 5 copies of rc.filter_configure_sync started not too far apart in time. Presumably one of these processes was hung up for some reason and held the filter lock. Then other things were queued up behind it.
I also noticed that there are Squid and SquidGuard processes out of /usr/pbi… and /usr/local... - that must be a "feature" of 2.1-DEV that I will also need to look into!
I will try to reproduce this, and see if it can happen after a clean shutdown, or if it only happens after a power-off and fsck on startup.
Does anyone else experience startup hangs/delays?
If so, what are you running - nanobsd/embedded hardware or other? 2.0.n or 2.1-DEV or both? what mix of packages? any other interesting environment?
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.