Actions
Bug #13067
closed
Resolve interval for ``filterdns`` may not match the configured value
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
Updated by Viktor Gurov over 2 years ago
- Related to Feature #13057: GUI option for IPsec ``dns-interval`` setting added
Updated by Reid Linnemann about 2 years 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
Updated by Reid Linnemann about 2 years ago
- Related to Bug #9296: Alias content is sometimes incomplete when an alias contains both FQDN and IP address entries added
Updated by Jim Pingle about 2 years ago
- Plus Target Version changed from 22.11 to 23.01
Updated by Danilo Zrenjanin about 2 years 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.
Updated by Reid Linnemann almost 2 years ago
- Status changed from New to Resolved
This issue only addresses the filter interval, which has been confirmed to be correct.
Updated by Jim Pingle almost 2 years 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