Project

General

Profile

Bug #7143

filterdns is triggering every 16 seconds for hosts even when the DNS record has not changed

Added by Jim Pingle about 1 month ago. Updated 21 days ago.

Status:
Confirmed
Priority:
High
Category:
FilterDNS
Target version:
Start date:
01/19/2017
Due date:
% Done:

100%

Affected version:
2.4
Affected Architecture:
All

Description

filterdns is triggering every 16 seconds whether the record has changed or not. It happens for IPsec entries and FQDNs in aliases.

Example 1: A firewall with an IPsec tunnel using a hostname for the peer address

The running command:

/usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 60 -c /var/etc/ipsec/filterdns-ipsec.hosts -d 1

Its configuration file (hostname redacted):

: cat /var/etc/ipsec/filterdns-ipsec.hosts
cmd hostname.example.com '/usr/local/sbin/pfSctl -c "service reload ipsecdns"'

System log:

Jan 19 09:05:45 bill php-fpm[39663]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:05:45 bill check_reload_status: Reloading filter
Jan 19 09:05:45 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:06:01 bill php-fpm: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:06:01 bill check_reload_status: Reloading filter
Jan 19 09:06:01 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:06:17 bill php-fpm[86255]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:06:18 bill check_reload_status: Reloading filter
Jan 19 09:06:18 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:06:34 bill php-fpm[39663]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:06:34 bill check_reload_status: Reloading filter
Jan 19 09:06:34 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:06:50 bill php-fpm: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:06:50 bill check_reload_status: Reloading filter
Jan 19 09:06:50 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:07:06 bill php-fpm[86255]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:07:06 bill check_reload_status: Reloading filter
Jan 19 09:07:06 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:07:22 bill php-fpm[39663]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:07:22 bill check_reload_status: Reloading filter
Jan 19 09:07:23 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:07:39 bill php-fpm: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:07:39 bill check_reload_status: Reloading filter
Jan 19 09:07:40 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:07:56 bill php-fpm[86255]: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:07:56 bill check_reload_status: Reloading filter
Jan 19 09:07:56 bill check_reload_status: Restarting ipsec tunnels
Jan 19 09:08:12 bill php-fpm: /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 19 09:08:12 bill check_reload_status: Reloading filter
Jan 19 09:08:13 bill check_reload_status: Restarting ipsec tunnels

Resolver Log:

Jan 19 09:05:45 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:05:45 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:06:01 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:06:01 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:06:18 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:06:18 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:06:34 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:06:34 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:06:50 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:06:50 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:07:06 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:07:06 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:07:23 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:07:23 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:07:40 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:07:40 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:07:56 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:07:56 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com
Jan 19 09:08:13 bill filterdns: clearing entry XXX.XXX.XXX.XXX from ipfw table  on host hostname.example.com
Jan 19 09:08:13 bill filterdns:     adding entry XXX.XXX.XXX.XXX to ipfw table  for host hostname.example.com

Since the entry did not change, it shouldn't have to trigger anything.

Looking at truss, it's clearing the entry before resolving the target. This whole block repeats every 16 seconds.

39847: _umtx_op(0x80064a008,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdfffd9c8) ERR#4 'Interrupted system call'
39847: SIGNAL 1 (SIGHUP)
39847: sigprocmask(SIG_SETMASK,{ SIGHUP },0x0)     = 0 (0x0)
39847: _umtx_op(0x8010167b8,UMTX_OP_NWAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
39847: sigreturn(0x7fffdfffd140)         ERR#4 'Interrupted system call'
39847: open("/var/etc/ipsec/filterdns-ipsec.hosts",O_RDONLY,0666) = 5 (0x5)
39847: fstat(5,{ mode=-rw-r--r-- ,inode=481684,size=79,blksize=32768 }) = 0 (0x0)
39847: read(5,"cmd hostname.example.com '/usr/l"...,32768) = 79 (0x4f)
39847: read(5,0x80106e400,32768)         = 0 (0x0)
39847: close(5)                     = 0 (0x0)
39847: sendto(4,"<13>Jan 19 09:11:12 filterdns: c"...,106,0x0,NULL,0x0) = 106 (0x6a)
39847: _umtx_op(0x80064a008,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdfffd9c8) = 0 (0x0)
39847: _umtx_op(0x801016cb8,UMTX_OP_NWAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
39847: _umtx_op(0x80101d000,UMTX_OP_RW_RDLOCK,0x0,0x0,0x0) = 0 (0x0)
39847: stat("/etc/nsswitch.conf",{ mode=-rw-r--r-- ,inode=802668,size=274,blksize=32768 }) = 0 (0x0)
39847: open("/etc/hosts",O_CLOEXEC,0666)     = 5 (0x5)
39847: fstat(5,{ mode=-rw-r--r-- ,inode=802604,size=182,blksize=32768 }) = 0 (0x0)
39847: read(5,"127.0.0.1\tlocalhost localhost.d"...,32768) = 182 (0xb6)
39847: read(5,0x80104fc00,32768)         = 0 (0x0)
39847: close(5)                     = 0 (0x0)
39847: stat("/etc/resolv.conf",{ mode=-rw-r--r-- ,inode=802607,size=123,blksize=32768 }) = 0 (0x0)
39847: socket(PF_INET,SOCK_DGRAM|SOCK_CLOEXEC,0) = 5 (0x5)
39847: connect(5,{ AF_INET 127.0.0.1:53 },16)     = 0 (0x0)
39847: sendto(5,"\M-&_\^A\0\0\^A\0\0\0\0\0\0\tjim"...,38,0x0,NULL,0x0) = 38 (0x26)
39847: poll({ 5/POLLRDNORM },1,5000)         = 1 (0x1)
39847: recvfrom(5,"\M-&_\M^A\M^@\0\^A\0\^A\0\^B\0\0"...,65536,0x0,{ AF_INET 127.0.0.1:53 },0x7fffdfffc468) = 101 (0x65)
39847: close(5)                     = 0 (0x0)
39847: socket(PF_INET,SOCK_DGRAM|SOCK_CLOEXEC,0) = 5 (0x5)
39847: connect(5,{ AF_INET 127.0.0.1:53 },16)     = 0 (0x0)
39847: sendto(5,"\M-d\M-X\^A\0\0\^A\0\0\0\0\0\0\t"...,38,0x0,NULL,0x0) = 38 (0x26)
39847: poll({ 5/POLLRDNORM },1,5000)         = 1 (0x1)
39847: recvfrom(5,"\M-d\M-X\M^A\M^@\0\^A\0\0\0\^A\0"...,65536,0x0,{ AF_INET 127.0.0.1:53 },0x7fffdfffc468) = 95 (0x5f)
39847: close(5)                     = 0 (0x0)
39847: sendto(4,"<13>Jan 19 09:11:12 filterdns: "...,104,0x0,NULL,0x0) = 104 (0x68)
39847: sigprocmask(SIG_BLOCK,{ SIGINT|SIGQUIT|SIGCHLD },{ }) = 0 (0x0)
81661: <new process>
39847: vfork()                     = 81661 (0x13efd)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: execve("/bin/sh",0x7fffdfffd850,0x7fffffffecc0) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ SIGINT|SIGQUIT|SIGCHLD }) = 0 (0x0)
81661: mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366304256 (0x800643000)
39847: sigaction(SIGINT,{ SIG_IGN 0x0 ss_t },{ 0x800835c30 SA_RESTART|SA_SIGINFO ss_t }) = 0 (0x0)
81661: issetugid()                 = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGINT|SIGQUIT|SIGCHLD },0x0) = 0 (0x0)
81661: lstat("/etc",{ mode=drwxr-xr-x ,inode=802560,size=4096,blksize=32768 }) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ SIGINT|SIGQUIT|SIGCHLD }) = 0 (0x0)
81661: lstat("/etc/libmap.conf",{ mode=-rw-r--r-- ,inode=802701,size=47,blksize=32768 }) = 0 (0x0)
39847: sigaction(SIGQUIT,{ SIG_IGN 0x0 ss_t },{ SIG_DFL 0x0 ss_t }) = 0 (0x0)
81661: openat(AT_FDCWD,"/etc/libmap.conf",O_CLOEXEC,00) = 4 (0x4)
39847: sigprocmask(SIG_SETMASK,{ SIGINT|SIGQUIT|SIGCHLD },0x0) = 0 (0x0)
81661: fstat(4,{ mode=-rw-r--r-- ,inode=802701,size=47,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,47,PROT_READ,MAP_PRIVATE,4,0x0)     = 34366337024 (0x80064b000)
81661: close(4)                     = 0 (0x0)
81661: lstat("/usr",{ mode=drwxr-xr-x ,inode=240769,size=512,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local",{ mode=drwxr-xr-x ,inode=240777,size=512,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local/etc",{ mode=drwxr-xr-x ,inode=242315,size=1536,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local/etc/libmap.d",0x7fffffffcca8) ERR#2 'No such file or directory'
81661: munmap(0x80064b000,47)             = 0 (0x0)
81661: openat(AT_FDCWD,"/var/run/ld-elf.so.hints",O_CLOEXEC,00) = 4 (0x4)
81661: read(4,"Ehnt\^A\0\0\0\M^@\0\0\0f\0\0\0\0"...,128) = 128 (0x80)
81661: fstat(4,{ mode=-r--r--r-- ,inode=6,size=230,blksize=32768 }) = 0 (0x0)
81661: lseek(4,0x80,SEEK_SET)             = 128 (0x80)
81661: read(4,"/lib:/usr/lib:/usr/lib/compat:/u"...,102) = 102 (0x66)
81661: close(4)                     = 0 (0x0)
81661: access("/lib/libedit.so.7",F_OK)         = 0 (0x0)
81661: openat(AT_FDCWD,"/lib/libedit.so.7",O_CLOEXEC|O_VERIFY,00) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=325415,size=224576,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,4,0x0) = 34366337024 (0x80064b000)
81661: mmap(0x0,2334720,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34368409600 (0x800845000)
81661: mmap(0x800845000,212992,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,4,0x0) = 34368409600 (0x800845000)
81661: mmap(0x800a79000,8192,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,4,0x34000) = 34370719744 (0x800a79000)
81661: mmap(0x800a7b000,16384,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34370727936 (0x800a7b000)
81661: munmap(0x80064b000,4096)             = 0 (0x0)
81661: close(4)                     = 0 (0x0)
81661: access("/lib/libc.so.7",F_OK)         = 0 (0x0)
81661: openat(AT_FDCWD,"/lib/libc.so.7",O_CLOEXEC|O_VERIFY,00) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=326497,size=1587808,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,4,0x0) = 34366337024 (0x80064b000)
81661: mmap(0x0,3784704,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34370744320 (0x800a7f000)
81661: mmap(0x800a7f000,1544192,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,4,0x0) = 34370744320 (0x800a7f000)
81661: mmap(0x800df7000,45056,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,4,0x178000) = 34374381568 (0x800df7000)
81661: mmap(0x800e02000,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34374426624 (0x800e02000)
81661: munmap(0x80064b000,4096)             = 0 (0x0)
81661: close(4)                     = 0 (0x0)
81661: access("/lib/libncursesw.so.8",F_OK)     = 0 (0x0)
81661: openat(AT_FDCWD,"/lib/libncursesw.so.8",O_CLOEXEC|O_VERIFY,00) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=326272,size=374864,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,4,0x0) = 34366337024 (0x80064b000)
81661: mmap(0x0,2473984,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34374529024 (0x800e1b000)
81661: mmap(0x800e1b000,356352,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,4,0x0) = 34374529024 (0x800e1b000)
81661: mmap(0x801071000,20480,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,4,0x56000) = 34376978432 (0x801071000)
81661: mmap(0x801076000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34376998912 (0x801076000)
81661: munmap(0x80064b000,4096)             = 0 (0x0)
81661: close(4)                     = 0 (0x0)
81661: munmap(0x80064a000,4096)             = 0 (0x0)
81661: mmap(0x0,40960,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366332928 (0x80064a000)
81661: munmap(0x80064d000,28672)         = 0 (0x0)
81661: mmap(0x0,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366345216 (0x80064d000)
81661: sysarch(AMD64_SET_FSBASE,0x7fffffffe678)     = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: readlink("/etc/malloc.conf",0x7fffffffdd70,1024) ERR#2 'No such file or directory'
81661: issetugid()                 = 0 (0x0)
81661: __sysctl(0x7fffffffdbe0,0x2,0x7fffffffdc30,0x7fffffffdc28,0x800bcba93,0xd) = 0 (0x0)
81661: __sysctl(0x7fffffffdc30,0x2,0x7fffffffdcf4,0x7fffffffdce8,0x0,0x0) = 0 (0x0)
81661: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34377003008 (0x801077000)
81661: munmap(0x801077000,2097152)         = 0 (0x0)
81661: mmap(0x0,4190208,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34377003008 (0x801077000)
81661: munmap(0x801077000,1609728)         = 0 (0x0)
81661: munmap(0x801400000,483328)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: getpid()                     = 81661 (0x13efd)
81661: geteuid()                 = 0 (0x0)
81661: getppid()                 = 39847 (0x9ba7)
81661: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34380709888 (0x801400000)
81661: getuid()                     = 0 (0x0)
81661: geteuid()                 = 0 (0x0)
81661: getgid()                     = 0 (0x0)
81661: getegid()                 = 0 (0x0)
81661: sigaction(SIGINT,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
81661: sigaction(SIGINT,{ 0x41b950 0x0 ss_t },0x0) = 0 (0x0)
81661: sigaction(SIGQUIT,0x0,{ SIG_DFL 0x0 ss_t }) = 0 (0x0)
81661: sigaction(SIGQUIT,{ 0x41b950 0x0 ss_t },0x0) = 0 (0x0)
81661: sigaction(SIGTERM,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
81661: sigaction(SIGTERM,{ SIG_DFL 0x0 ss_t },0x0) = 0 (0x0)
81661: stat(".",{ mode=drwxr-xr-x ,inode=2,size=1024,blksize=32768 }) = 0 (0x0)
81661: stat("/usr/local/www",{ mode=drwxr-xr-x ,inode=242314,size=8192,blksize=32768 }) = 0 (0x0)
81661: __getcwd("/",256)             = 0 (0x0)
81661: execve("/usr/local/sbin/pfSctl",0x8014180e0,0x801418178) = 0 (0x0)
81661: mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366160896 (0x800620000)
81661: issetugid()                 = 0 (0x0)
81661: lstat("/etc",{ mode=drwxr-xr-x ,inode=802560,size=4096,blksize=32768 }) = 0 (0x0)
81661: lstat("/etc/libmap.conf",{ mode=-rw-r--r-- ,inode=802701,size=47,blksize=32768 }) = 0 (0x0)
81661: openat(AT_FDCWD,"/etc/libmap.conf",O_CLOEXEC,00) = 4 (0x4)
81661: fstat(4,{ mode=-rw-r--r-- ,inode=802701,size=47,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,47,PROT_READ,MAP_PRIVATE,4,0x0)     = 34366193664 (0x800628000)
81661: close(4)                     = 0 (0x0)
81661: lstat("/usr",{ mode=drwxr-xr-x ,inode=240769,size=512,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local",{ mode=drwxr-xr-x ,inode=240777,size=512,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local/etc",{ mode=drwxr-xr-x ,inode=242315,size=1536,blksize=32768 }) = 0 (0x0)
81661: lstat("/usr/local/etc/libmap.d",0x7fffffffcca8) ERR#2 'No such file or directory'
81661: munmap(0x800628000,47)             = 0 (0x0)
81661: openat(AT_FDCWD,"/var/run/ld-elf.so.hints",O_CLOEXEC,00) = 4 (0x4)
81661: read(4,"Ehnt\^A\0\0\0\M^@\0\0\0f\0\0\0\0"...,128) = 128 (0x80)
81661: fstat(4,{ mode=-r--r--r-- ,inode=6,size=230,blksize=32768 }) = 0 (0x0)
81661: lseek(4,0x80,SEEK_SET)             = 128 (0x80)
81661: read(4,"/lib:/usr/lib:/usr/lib/compat:/u"...,102) = 102 (0x66)
81661: close(4)                     = 0 (0x0)
81661: access("/lib/libc.so.7",F_OK)         = 0 (0x0)
81661: openat(AT_FDCWD,"/lib/libc.so.7",O_CLOEXEC|O_VERIFY,00) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=326497,size=1587808,blksize=32768 }) = 0 (0x0)
81661: mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,4,0x0) = 34366193664 (0x800628000)
81661: mmap(0x0,3784704,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34368266240 (0x800822000)
81661: mmap(0x800822000,1544192,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,4,0x0) = 34368266240 (0x800822000)
81661: mmap(0x800b9a000,45056,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,4,0x178000) = 34371903488 (0x800b9a000)
81661: mmap(0x800ba5000,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34371948544 (0x800ba5000)
81661: munmap(0x800628000,4096)             = 0 (0x0)
81661: close(4)                     = 0 (0x0)
81661: munmap(0x800627000,4096)             = 0 (0x0)
81661: mmap(0x0,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366189568 (0x800627000)
81661: sysarch(AMD64_SET_FSBASE,0x7fffffffe678)     = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: readlink("/etc/malloc.conf",0x7fffffffdd70,1024) ERR#2 'No such file or directory'
81661: issetugid()                 = 0 (0x0)
81661: __sysctl(0x7fffffffdbe0,0x2,0x7fffffffdc30,0x7fffffffdc28,0x80096ea93,0xd) = 0 (0x0)
81661: __sysctl(0x7fffffffdc30,0x2,0x7fffffffdcf4,0x7fffffffdce8,0x0,0x0) = 0 (0x0)
81661: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34372050944 (0x800bbe000)
81661: munmap(0x800bbe000,2097152)         = 0 (0x0)
81661: mmap(0x0,4190208,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34372050944 (0x800bbe000)
81661: munmap(0x800bbe000,270336)         = 0 (0x0)
81661: munmap(0x800e00000,1822720)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34374418432 (0x800e00000)
81661: access("/etc/localtime",R_OK)         = 0 (0x0)
81661: open("/etc/localtime",O_RDONLY,037777777600) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=802598,size=1649,blksize=32768 }) = 0 (0x0)
81661: read(4,"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,41448) = 1649 (0x671)
81661: close(4)                     = 0 (0x0)
81661: issetugid()                 = 0 (0x0)
81661: open("/usr/share/zoneinfo/posixrules",O_RDONLY,00) = 4 (0x4)
81661: fstat(4,{ mode=-r--r--r-- ,inode=244110,size=3519,blksize=32768 }) = 0 (0x0)
81661: read(4,"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,41448) = 3519 (0xdbf)
81661: close(4)                     = 0 (0x0)
81661: sigaction(SIGALRM,{ 0x401430 SA_RESTART|SA_SIGINFO ss_t },0x0) = 0 (0x0)
81661: socket(PF_LOCAL,SOCK_STREAM,0)         = 4 (0x4)
81661: setitimer(0,{ 0.000000, 3.000000 },{ 0.000000, 0.000000 }) = 0 (0x0)
81661: connect(4,{ AF_UNIX "/var/run/check_reload_status" },106) = 0 (0x0)
81661: setitimer(0,{ 0.000000, 0.000000 },{ 0.000000, 2.998796 }) = 0 (0x0)
81661: setitimer(0,{ 0.000000, 3.000000 },{ 0.000000, 0.000000 }) = 0 (0x0)
81661: write(4,"service reload ipsecdns",23)     = 23 (0x17)
81661: setitimer(0,{ 0.000000, 0.000000 },{ 0.000000, 2.998951 }) = 0 (0x0)
81661: setitimer(0,{ 0.000000, 3.000000 },{ 0.000000, 0.000000 }) = 0 (0x0)
81661: read(4,"OK\n",2048)             = 3 (0x3)
81661: fstat(1,{ mode=crw-rw-rw- ,inode=22,size=0,blksize=4096 }) = 0 (0x0)
81661: ioctl(1,TIOCGETA,0xffffdd60)         ERR#25 'Inappropriate ioctl for device'
81661: close(4)                     = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
81661: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)
81661: write(1,"OK\n",3)             = 3 (0x3)
81661: exit(0x0)                
81661: process exit, rval = 0
39847: wait4(81661,{ EXITED,val=0 },0x0,0x0)     = 81661 (0x13efd)
39847: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ SIGINT|SIGQUIT|SIGCHLD }) = 0 (0x0)
39847: sigaction(SIGINT,{ 0x800835c30 SA_RESTART|SA_SIGINFO ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGINT|SIGQUIT|SIGCHLD },0x0) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ SIGINT|SIGQUIT|SIGCHLD }) = 0 (0x0)
39847: sigaction(SIGQUIT,{ SIG_DFL 0x0 ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ SIGINT|SIGQUIT|SIGCHLD },0x0) = 0 (0x0)
39847: sigprocmask(SIG_SETMASK,{ },0x0)         = 0 (0x0)

History

#1 Updated by Renato Botelho 26 days ago

This only happens when config file uses the directive 'cmd', in this case, ipsec session is using it:

cmd hostname.example.com '/usr/local/sbin/pfSctl -c "service reload ipsecdns"'

Looks like this regression was introduces by commit https://github.com/pfsense/FreeBSD-ports/commit/bda9da32e28a97c4e1fb4c56c0fca8a5a1ed4907

#2 Updated by Renato Botelho 24 days ago

  • Status changed from Confirmed to Feedback
  • Assignee set to Renato Botelho
  • % Done changed from 0 to 100

I've pushed a fix on filterdns 1.0_16 that will make it to run defined cmd only when IP address changes.

#3 Updated by Luiz Otavio O Souza 21 days ago

  • Assignee changed from Renato Botelho to Luiz Otavio O Souza

I'll take it, something is fishy here.

#4 Updated by Luiz Otavio O Souza 21 days ago

  • Status changed from Feedback to Confirmed

Ooops, there is a loop in rc.newipsecdns, which triggers a filterdns reload, which runs rc.newipsecdns again (where you can find a sleep(15) which would fit the 'every 16 seconds').

Also available in: Atom PDF