Project

General

Profile

Actions
Copy link

Bug #13067

closed

Resolve interval for ``filterdns`` may not match the configured value

Added by Marcos M about 2 years ago. Updated over 1 year ago.

Status:
Resolved
Priority:
Normal
Assignee:
Reid Linnemann
Category:
FilterDNS
Target version:
2.7.0
Start date:
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
23.01
Release Notes:
Default
Affected Version:
Affected Architecture:

Description

Tested on 22.05.a.20220417.0600.

Tested with the feature from:
https://redmine.pfsense.org/issues/13057

The interval is added correctly:

root 62793 0.0 0.3 12140 2784 - Is 18:44 0:00.01 |-- /usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 10 -c /var/etc/ipsec/filterdns-ipsec.hosts -d 1

However, the actual resolve interval seems to be done at twice the value in the config (tested with 10 and 15 second intervals - reboot after each change):

DNS Resolver logs with verbosity 3:

Apr 17 18:47:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Apr 17 18:47:14     unbound     62371     [62371:0] info: resolving siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: processQueryTargets: siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: sending query: siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] debug: sending to target: <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:14     unbound     62371     [62371:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0
Apr 17 18:47:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Apr 17 18:47:14     unbound     62371     [62371:0] info: iterator operate: query siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: response for siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: reply from <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:14     unbound     62371     [62371:0] info: query response was ANSWER
Apr 17 18:47:14     unbound     62371     [62371:0] info: finishing processing for siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:14     unbound     62371     [62371:0] debug: cache memory msg=66287 rrset=66277 infra=8066 val=0
Apr 17 18:47:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Apr 17 18:47:14     unbound     62371     [62371:0] info: resolving siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: processQueryTargets: siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: sending query: siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] debug: sending to target: <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:14     unbound     62371     [62371:0] debug: cache memory msg=66287 rrset=66277 infra=8066 val=0
Apr 17 18:47:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Apr 17 18:47:14     unbound     62371     [62371:0] info: iterator operate: query siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: response for siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] info: reply from <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:14     unbound     62371     [62371:0] info: query response was nodata ANSWER
Apr 17 18:47:14     unbound     62371     [62371:0] info: finishing processing for siteb.dyndns.lab.arpa. AAAA IN
Apr 17 18:47:14     unbound     62371     [62371:0] debug: cache memory msg=66502 rrset=66526 infra=8066 val=0
Apr 17 18:47:44     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Apr 17 18:47:44     unbound     62371     [62371:0] info: resolving siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] info: processQueryTargets: siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] info: sending query: siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] debug: sending to target: <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:44     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Apr 17 18:47:44     unbound     62371     [62371:0] info: iterator operate: query siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] info: response for siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] info: reply from <lab.arpa.> 10.0.5.200#53
Apr 17 18:47:44     unbound     62371     [62371:0] info: query response was ANSWER
Apr 17 18:47:44     unbound     62371     [62371:0] info: finishing processing for siteb.dyndns.lab.arpa. A IN
Apr 17 18:47:44     unbound     62371     [62371:0] debug: cache memory msg=66502 rrset=66526 infra=8066 val=0
Apr 17 18:48:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Apr 17 18:48:14     unbound     62371     [62371:0] info: resolving siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] info: processQueryTargets: siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] info: sending query: siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] debug: sending to target: <lab.arpa.> 10.0.5.200#53
Apr 17 18:48:14     unbound     62371     [62371:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Apr 17 18:48:14     unbound     62371     [62371:0] info: iterator operate: query siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] info: response for siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] info: reply from <lab.arpa.> 10.0.5.200#53
Apr 17 18:48:14     unbound     62371     [62371:0] info: query response was ANSWER
Apr 17 18:48:14     unbound     62371     [62371:0] info: finishing processing for siteb.dyndns.lab.arpa. A IN
Apr 17 18:48:14     unbound     62371     [62371:0] debug: cache memory msg=66502 rrset=66526 infra=8066 val=0

DNS Resolver logs with filderdns verbosity 99:

Apr 17 19:06:43     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:06:43     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:07:02     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:07:02     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:07:22     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:07:22     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:07:42     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:07:42     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:08:02     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:08:02     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:08:22     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:08:22     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:08:42     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:08:42     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:09:02     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:09:02     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:09:22     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:09:22     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:09:42     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:09:42     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa
Apr 17 19:10:02     filterdns     94859     Awaking from the sleep for hostname siteb.dyndns.lab.arpa (1)
Apr 17 19:10:02     filterdns     94859     found address 198.51.100.2 for host siteb.dyndns.lab.arpa

Related issues

Related to Feature #13057: GUI option for IPsec ``dns-interval`` settingResolvedViktor Gurov

Actions
Related to Bug #9296: Alias content is sometimes incomplete when an alias contains both FQDN and IP address entriesResolvedReid Linnemann

Actions
Actions
Copy link
 #1

Updated by Viktor Gurov about 2 years ago

  • Related to Feature #13057: GUI option for IPsec ``dns-interval`` setting added
Actions
Copy link
 #2

Updated by Reid Linnemann over 1 year ago

  • Status changed from New to Feedback
  • Assignee set to Reid Linnemann
  • Target version set to 2.7.0
  • Plus Target Version set to 22.11

The code inexplicably added the interval mod 30 to the interval, I've fixed this as of https://github.com/pfsense/FreeBSD-ports/commit/d522e1f53e53bf70438e02ac1d00b1f1feb733fa as part of fixes for #9296

Actions
Copy link
 #3

Updated by Reid Linnemann over 1 year ago

  • Related to Bug #9296: Alias content is sometimes incomplete when an alias contains both FQDN and IP address entries added
Actions
Copy link
 #4

Updated by Jim Pingle over 1 year ago

  • Plus Target Version changed from 22.11 to 23.01
Actions
Copy link
 #5

Updated by Danilo Zrenjanin over 1 year ago

  • Status changed from Feedback to New

Tested against:

2.7.0-DEVELOPMENT (amd64)
built on Fri Oct 28 06:06:25 UTC 2022
FreeBSD 14.0-CURRENT

the interval of 10s was added correctly:

root    73776   0.0  0.2  21772  3668  -  Is   18:01      0:00.02 /usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 10 -c /var/etc/ipsec/filterdns-ipsec.hosts -d 1

However, the resolver logs with verbosity level 3 set didn't show any queries for the defined hostname in Phase 1.

Here are the only relevant logs for that hostname in the resolver logs:

cat /var/log/resolver.log | grep pftest2.ipbgd.office
Oct 29 18:00:55 pfdev filterdns[14523]:     Adding Action: cmd cmd: /usr/local/sbin/pfSctl -c "service reload ipsecdns" host: pftest2.ipbgd.office
Oct 29 18:00:55 pfdev filterdns[14523]:         Adding host pftest2.ipbgd.office
Oct 29 18:01:06 pfdev filterdns[72840]:     Adding Action: cmd cmd: /usr/local/sbin/pfSctl -c "service reload ipsecdns" host: pftest2.ipbgd.office
Oct 29 18:01:06 pfdev filterdns[72840]:         Adding host pftest2.ipbgd.office
Oct 29 18:01:12 pfdev filterdns[72840]:     Adding Action: cmd cmd: /usr/local/sbin/pfSctl -c "service reload ipsecdns" host: pftest2.ipbgd.office
Oct 29 18:01:29 pfdev filterdns[72840]:     Adding Action: cmd cmd: /usr/local/sbin/pfSctl -c "service reload ipsecdns" host: pftest2.ipbgd.office
Oct 29 18:02:57 pfdev filterdns[72840]:     Adding Action: cmd cmd: /usr/local/sbin/pfSctl -c "service reload ipsecdns" host: pftest2.ipbgd.office

Please check again.

Actions
Copy link
 #6

Updated by Reid Linnemann over 1 year ago

  • Status changed from New to Resolved

This issue only addresses the filter interval, which has been confirmed to be correct.

Actions
Copy link
 #7

Updated by Jim Pingle over 1 year ago

  • Subject changed from filterdns resolve interval is twice the intended value to Resolve interval for ``filterdns`` may not match the configured value

Updating subject for release notes.

Actions
Copy link

Also available in: Atom PDF