Project

General

Profile

Actions
Copy link

Bug #6494

closed

Hang during bootup on lock('filter.lock')

Added by Harry Coin over 8 years ago. Updated over 8 years ago.

Status:
Resolved
Priority:
High
Assignee:
Luiz Souza
Category:
Unknown
Target version:
2.3.2
Start date:
06/16/2016
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
All
Affected Architecture:

Description

Hang during bootup 3 of 5 tries on lock('filter.lock')

Why does filterlog hold /tmp/filter.lock open for writing?

To see this, I added these debug writes to /etc/inc/filter.inc:

...
echo "1\n";
/* Use filter lock to not allow concurrent filter reloads during this run. */
$filterlck = lock('filter', LOCK_EX);
echo "2\n";

filter_pflog_start();
echo "3\n";
        update_filter_reload_status(gettext("Initializing"));
echo "4\n";
/* invalidate interface cache */
        get_interface_arr(true);
echo "5\n";
if (isset($config['system']['developerspew'])) {
                $mt = microtime();
                echo "filter_configure_sync() being called $mt\n";
        }
        /* Get interface list to work with. */
        filter_generate_optcfg_array();
echo "6\n";
        if (platform_booting()  true) {
                echo gettext("Configuring firewall");
        }
/* generate aliases */
        if (platform_booting()  true) {
                echo ".";
        }
echo "7\n";
        update_filter_reload_status(gettext("Creating aliases"));
...

and /etc/inc/util.inc:
...
function lock($lock, $op = LOCK_SH) {
global $g, $cfglckkeyconsumers;
if (!$lock) {
die(gettext("WARNING: A name must be given as parameter to lock() function."));
}
if (!file_exists("{$g['tmp_path']}/{$lock}.lock")) {
echo "making {$g['tmp_path']}/{$lock}.lock\n";
@touch("{$g['tmp_path']}/{$lock}.lock");
@chmod("{$g['tmp_path']}/{$lock}.lock", 0666);
}
$cfglckkeyconsumers++;
echo "locking {$g['tmp_path']}/{$lock}.lock, count {$cfglckkeyconsumers}\n";
...

Heres's the boot trace on the serial console:

Welcome to pfSense 2.3.1-RELEASE (Patch 1) on the 'pfSense' platform...

No core dumps found.
Creating symlinks......ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib /usr/local/lib/ipsec
32-bit compatibility ldconfig path: /usr/lib32
done.
making /tmp/config.lock
locking /tmp/config.lock, count 1
External config loader 1.0 is now starting... vtbd0s1w starting... vtbd0s1a
Launching the init system.....locking /tmp/config.lock, count 1
.. done.
Initializing.................. done.
Starting device manager (devd)...done.
Loading configuration....locking /tmp/config.lock, count 2
locking /tmp/config.lock, count 3
..done.
Updating configuration...done.
Cleaning backup cache.................................done.
Setting up extended sysctls...done.
Setting timezone...done.
Configuring loopback interface...done.
Starting syslog...done.
Starting Secure Shell Services...done.
Setting up polling defaults...done.
Setting up interfaces microcode...done.
Configuring loopback interface...done.
Creating wireless clone interfaces...done.
Configuring LAGG interfaces...done.
Configuring VLAN interfaces...done.
Configuring QinQ interfaces...done.
Configuring ISP1 interface...done.
Configuring LAN interface...done.
Configuring ISP2 interface...done.
Configuring CARP settings...done.
Configuring PFSYNC interface...done.
Configuring CARP settings...done.
Syncing OpenVPN settings...tap1: Ethernet address: xxxxx
done. << NOTE: Maybe a 4 sec delay here >>
locking /tmp/resolvconf.lock, count 4
resolv.conf generated.
1
locking /tmp/filter.lock, count 5

... N.B. Magically, the file /tmp/filter.lock must already exist as the 'making' debug write never runs.
... ssh works at this point, bootup hangs here forever. Logging in by ssh gets:

fuser /tmp/filter.lock
/tmp/filter.lock:  2792w 90560w 36404w   299w

Notice: there is no report of any lock being held.
[2.3.1-RELEASE][]/root: ps axu | grep 2792
root 2792 0.0 1.6 268248 33408 - I 11:39AM 0:00.11 php-fpm: pool nginx (php-fpm)
[2.3.1-RELEASE][]/root: ps axu | grep 90560
root 90560 0.0 1.6 268248 33760 - I 11:39AM 0:02.26 php-fpm: pool nginx (php-fpm)
[2.3.1-RELEASE][]/root: ps axu | grep 36404
root 36404 0.0 0.1 16676 2088 - Ss 11:39AM 0:00.01 /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
[2.3.1-RELEASE][]/root: ps axu | grep 299
root 299 0.0 1.9 272244 39260 u0 I+ 11:38AM 0:41.37 /usr/local/bin/php-cgi -f /etc/rc.bootup

Killing off filterlog by
$kill 36404
allows boot to continue, whereafter we get normal operations (including a restart of filterlog).
.. bootup log continues:

2
3
4
5
6
Configuring firewall.7
.....done.
Starting PFLOG...done.
Setting up gateway monitors...done.
Synchronizing user settings...done.
Starting webConfigurator...done.
Configuring CRON...done.
Starting DNS Resolver...done.
Starting NTP time client...done.
Starting DHCP service...done.
Starting DHCPv6 service...done.
1
locking /tmp/filter.lock, count 6
2
3
4
5
6
Configuring firewall.7
.....done.
making /tmp/ipsec.lock
locking /tmp/ipsec.lock, count 7
Generating RRD graphs...done.
Starting syslog...done.
Starting CRON... done.
locking /tmp/config.lock, count 1
Starting package arping...done.
Starting package bind...locking /tmp/config.lock, count 2
done.
Starting package iperf...done.
Starting package Notes...done.
Starting package nut...done.
Starting package OpenVPN Client Export Utility...done.
Starting package squid3...done.
Starting /usr/local/etc/rc.d/named.sh...done.
Starting /usr/local/etc/rc.d/sqp_monitor.sh...done.
locking /tmp/config.lock, count 1
locking /tmp/config.lock, count 1
pfSense (pfSense) 2.3.1-RELEASE (Patch 1) amd64 Wed May 25 14:53:06 CDT 2016
Bootup complete

FreeBSD/amd64 (gate1.quietfountain.com) (ttyu0)

locking /tmp/config.lock, count 1
  • Welcome to pfSense 2.3.1-RELEASE-p1 (amd64 full-install) on ....
Actions
Copy link

Also available in: Atom PDF