Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug] Prometheus blocky_prefetch_domain_name_cache_count showing inconsistent values if bootstrap is enabled #891

Closed
adb76 opened this issue Feb 21, 2023 · 4 comments · Fixed by #915
Labels
🐞 bug Something isn't working
Milestone

Comments

@adb76
Copy link

adb76 commented Feb 21, 2023

Hello,

I'm using blocky 0.20. After playing a little bit around with the prefetch configuration and looking on the prometheus stats I saw that the value blocky_prefetch_domain_name_cache_count sometimes jumps down to the value "7" and than after a few seconds up again to the value before. You can see that here directly on the graph:

grafik

Since it doesn't seem for me that the prefetch cache is cleared, is it only a reporting error of the prometheus endpoint?

Here you can see my current config:

upstream:
  default:
    - https://dns.quad9.net/dns-query
    - https://1.1.1.1/dns-query
    - https://dns0.eu

connectIPVersion: v4

clientLookup:
  upstream: 192.168.2.1
  singleNameOrder:
    - 1

conditional:
  mapping:
    fritz.box: 192.168.2.1
    168.192.in-addr.arpa: 192.168.2.1

blocking:
  blackLists:
    ads:
      - /app/blacklist.txt
      - https://raw.githubusercontent.com/hagezi/dns-blocklists/main/hosts/pro.plus.txt
      - https://gitlab.com/hagezi/mirror/-/raw/main/dns-blocklists/hosts/pro.plus.txt
    clean:
      - https://nsfw.oisd.nl/domains
    regional:
      - |
        # inline definition with YAML literal block scalar style
        /\.cn$/
        /\.ru$/
    empty:
  whiteLists:
    ads:
      - /app/whitelist.txt

  clientGroupsBlock:
    default:
      - ads
      - clean
      - regional

caching:
  minTime: 24h
  prefetching: true
  prefetchExpires: 6h
  prefetchThreshold: 6
  cacheTimeNegative: 24h

redis:
  address: 192.168.2.30:6379
  database: 0
  required: true
  connectionAttempts: 10
  connectionCooldown: 3s

queryLog:
  type: mysql
  target: (removed)
  logRetentionDays: 7
  creationAttempts: 6
  creationCooldown: 10s

port: 53
httpPort: 4000
bootstrapDns: tcp+udp:9.9.9.9

prometheus:
  enable: true

Kind regards.

@0xERR0R
Copy link
Owner

0xERR0R commented Feb 22, 2023

It looks strange... Do you see some errors/warnings in log?

@adb76
Copy link
Author

adb76 commented Feb 22, 2023

No, there aren't any errors in the log - e.g. this is the log from today:

[2023-02-22 08:03:14]  INFO list_cache: group import finished group=regional total_count=2
[2023-02-22 08:03:14]  INFO list_cache: group import finished group=empty total_count=0
[2023-02-22 12:02:54]  INFO list_cache: starting processing of file file=/app/blacklist.txt
[2023-02-22 12:02:54]  INFO list_cache: starting download link=https://raw.githubusercontent.com/hagezi/dns-blocklists/main/hosts/pro.plus.txt
[2023-02-22 12:02:54]  INFO list_cache: file imported count=5 source=/app/blacklist.txt
[2023-02-22 12:02:54]  INFO list_cache: starting download link=https://gitlab.com/hagezi/mirror/-/raw/main/dns-blocklists/hosts/pro.plus.txt
[2023-02-22 12:02:54]  INFO list_cache: starting processing of file file=/app/whitelist.txt
[2023-02-22 12:02:54]  INFO list_cache: file imported count=0 source=/app/whitelist.txt
[2023-02-22 12:02:54]  INFO list_cache: group import finished group=ads total_count=0
[2023-02-22 12:03:13]  INFO list_cache: file imported count=1420022 source=https://gitlab.com/hagezi/mirror/-/raw/main/dns-blocklists/hosts/pro.plus.txt
[2023-02-22 12:03:14]  INFO list_cache: file imported count=1420022 source=https://raw.githubusercontent.com/hagezi/dns-blocklists/main/hosts/pro.plus.txt
[2023-02-22 12:03:14]  INFO list_cache: group import finished group=ads total_count=1420027
[2023-02-22 12:03:14]  INFO list_cache: starting download link=https://nsfw.oisd.nl/domains
[2023-02-22 12:03:15]  INFO list_cache: file imported count=436238 source=https://nsfw.oisd.nl/domains
[2023-02-22 12:03:15]  INFO list_cache: group import finished group=clean total_count=436238
[2023-02-22 12:03:15]  INFO list_cache: file imported count=2 source=# inline definition with YAML literal block scalar style
/\.cn$/
/\.ru$/

[2023-02-22 12:03:15]  INFO list_cache: group import finished group=regional total_count=2
[2023-02-22 12:03:15]  INFO list_cache: group import finished group=empty total_count=0
[2023-02-22 16:02:55]  INFO list_cache: starting processing of file file=/app/blacklist.txt
[2023-02-22 16:02:55]  INFO list_cache: starting download link=https://gitlab.com/hagezi/mirror/-/raw/main/dns-blocklists/hosts/pro.plus.txt
[2023-02-22 16:02:55]  INFO list_cache: file imported count=5 source=/app/blacklist.txt
[2023-02-22 16:02:55]  INFO list_cache: starting download link=https://raw.githubusercontent.com/hagezi/dns-blocklists/main/hosts/pro.plus.txt
[2023-02-22 16:02:55]  INFO list_cache: starting processing of file file=/app/whitelist.txt
[2023-02-22 16:02:55]  INFO list_cache: file imported count=0 source=/app/whitelist.txt
[2023-02-22 16:02:55]  INFO list_cache: group import finished group=ads total_count=0
[2023-02-22 16:03:15]  INFO list_cache: file imported count=1418916 source=https://gitlab.com/hagezi/mirror/-/raw/main/dns-blocklists/hosts/pro.plus.txt
[2023-02-22 16:03:16]  INFO list_cache: file imported count=1418916 source=https://raw.githubusercontent.com/hagezi/dns-blocklists/main/hosts/pro.plus.txt
[2023-02-22 16:03:16]  INFO list_cache: group import finished group=ads total_count=1418921
[2023-02-22 16:03:16]  INFO list_cache: starting download link=https://nsfw.oisd.nl/domains
[2023-02-22 16:03:16]  INFO list_cache: file imported count=436692 source=https://nsfw.oisd.nl/domains
[2023-02-22 16:03:16]  INFO list_cache: group import finished group=clean total_count=436692
[2023-02-22 16:03:16]  INFO list_cache: file imported count=2 source=# inline definition with YAML literal block scalar style
/\.cn$/
/\.ru$/

[2023-02-22 16:03:16]  INFO list_cache: group import finished group=regional total_count=2
[2023-02-22 16:03:16]  INFO list_cache: group import finished group=empty total_count=0

This is the stats for blocky_prefetch_domain_name_cache_count from the last two hours:

grafik

Everything else looks quite "normal":

grafik

grafik

grafik

@adb76
Copy link
Author

adb76 commented Feb 23, 2023

So I analyzed a little bit more::

Directly after the start of blocky some values in the Prometheus endpoint initializes with the value 7:

# HELP blocky_blacklist_cache Number of entries in the blacklist cache
# TYPE blocky_blacklist_cache gauge
blocky_blacklist_cache{group="ads"} 1.406685e+06
blocky_blacklist_cache{group="clean"} 436754
blocky_blacklist_cache{group="empty"} 0
blocky_blacklist_cache{group="regional"} 2
# HELP blocky_blocking_enabled Blocking status
# TYPE blocky_blocking_enabled gauge
blocky_blocking_enabled 1
# HELP blocky_build_info Version number and build info
# TYPE blocky_build_info gauge
blocky_build_info{build_time="20221112-204544",version="v0.20"} 1
# HELP blocky_cache_entry_count Number of entries in cache
# TYPE blocky_cache_entry_count gauge
blocky_cache_entry_count 7
# HELP blocky_cache_hit_count Cache hit counter
# TYPE blocky_cache_hit_count counter
blocky_cache_hit_count 4
# HELP blocky_cache_miss_count Cache miss counter
# TYPE blocky_cache_miss_count counter
blocky_cache_miss_count 7
# HELP blocky_error_total Number of total errors
# TYPE blocky_error_total counter
blocky_error_total 0
# HELP blocky_failed_download_count Failed download counter
# TYPE blocky_failed_download_count counter
blocky_failed_download_count 0
# HELP blocky_last_list_group_refresh Timestamp of last list refresh
# TYPE blocky_last_list_group_refresh gauge
blocky_last_list_group_refresh 1.67713743e+09
# HELP blocky_prefetch_count Prefetch counter
# TYPE blocky_prefetch_count counter
blocky_prefetch_count 0
# HELP blocky_prefetch_domain_name_cache_count Number of entries in domain cache
# TYPE blocky_prefetch_domain_name_cache_count gauge
blocky_prefetch_domain_name_cache_count 7
# HELP blocky_prefetch_hit_count Prefetch hit counter
# TYPE blocky_prefetch_hit_count counter
blocky_prefetch_hit_count 0
# HELP blocky_whitelist_cache Number of entries in the whitelist cache
# TYPE blocky_whitelist_cache gauge
blocky_whitelist_cache{group="ads"} 0

After some seconds they are changing to the first "real" values:

# HELP blocky_blacklist_cache Number of entries in the blacklist cache
# TYPE blocky_blacklist_cache gauge
blocky_blacklist_cache{group="ads"} 1.406685e+06
blocky_blacklist_cache{group="clean"} 436754
blocky_blacklist_cache{group="empty"} 0
blocky_blacklist_cache{group="regional"} 2
# HELP blocky_blocking_enabled Blocking status
# TYPE blocky_blocking_enabled gauge
blocky_blocking_enabled 1
# HELP blocky_build_info Version number and build info
# TYPE blocky_build_info gauge
blocky_build_info{build_time="20221112-204544",version="v0.20"} 1
# HELP blocky_cache_entry_count Number of entries in cache
# TYPE blocky_cache_entry_count gauge
blocky_cache_entry_count 1
# HELP blocky_cache_hit_count Cache hit counter
# TYPE blocky_cache_hit_count counter
blocky_cache_hit_count 6
# HELP blocky_cache_miss_count Cache miss counter
# TYPE blocky_cache_miss_count counter
blocky_cache_miss_count 8
# HELP blocky_error_total Number of total errors
# TYPE blocky_error_total counter
blocky_error_total 0
# HELP blocky_failed_download_count Failed download counter
# TYPE blocky_failed_download_count counter
blocky_failed_download_count 0
# HELP blocky_last_list_group_refresh Timestamp of last list refresh
# TYPE blocky_last_list_group_refresh gauge
blocky_last_list_group_refresh 1.67713743e+09
# HELP blocky_prefetch_count Prefetch counter
# TYPE blocky_prefetch_count counter
blocky_prefetch_count 0
# HELP blocky_prefetch_domain_name_cache_count Number of entries in domain cache
# TYPE blocky_prefetch_domain_name_cache_count gauge
blocky_prefetch_domain_name_cache_count 7
# HELP blocky_prefetch_hit_count Prefetch hit counter
# TYPE blocky_prefetch_hit_count counter
blocky_prefetch_hit_count 0
# HELP blocky_query_total Number of total queries
# TYPE blocky_query_total counter
blocky_query_total{client="endeavour.fritz.box",type="A"} 4
# HELP blocky_request_duration_ms Request duration distribution
# TYPE blocky_request_duration_ms histogram
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="5"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="10"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="20"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="30"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="50"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="75"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="100"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="200"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="500"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="1000"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="2000"} 3
blocky_request_duration_ms_bucket{response_type="BLOCKED",le="+Inf"} 3
blocky_request_duration_ms_sum{response_type="BLOCKED"} 4
blocky_request_duration_ms_count{response_type="BLOCKED"} 3
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="5"} 0
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="10"} 0
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="20"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="30"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="50"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="75"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="100"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="200"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="500"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="1000"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="2000"} 1
blocky_request_duration_ms_bucket{response_type="RESOLVED",le="+Inf"} 1
blocky_request_duration_ms_sum{response_type="RESOLVED"} 14
blocky_request_duration_ms_count{response_type="RESOLVED"} 1
# HELP blocky_response_total Number of total responses
# TYPE blocky_response_total counter
blocky_response_total{reason="BLOCKED (ads)",response_code="NOERROR",response_type="BLOCKED"} 3
blocky_response_total{reason="RESOLVED (https://1.1.1.1/dns-query)",response_code="NOERROR",response_type="RESOLVED"} 1
# HELP blocky_whitelist_cache Number of entries in the whitelist cache
# TYPE blocky_whitelist_cache gauge
blocky_whitelist_cache{group="ads"} 0

I'm using blocky 0.20 with the latest docker image.

@0xERR0R 0xERR0R added the 🐞 bug Something isn't working label Mar 7, 2023
@0xERR0R 0xERR0R added this to the 0.21 milestone Mar 7, 2023
@0xERR0R 0xERR0R changed the title [Bug] Prometheus blocky_prefetch_domain_name_cache_count showing inconsistent values [Bug] Prometheus blocky_prefetch_domain_name_cache_count showing inconsistent values if bootstrap is enabled Mar 7, 2023
@0xERR0R
Copy link
Owner

0xERR0R commented Mar 7, 2023

I could reproduce the problem. It occurs only if bootstrap is enabled. Bootstrap uses internally also caching resolver with prefetching. We do also have 2 different caching resolvers with prefetching and both of them are emitting metrics. Sometimes you can see "7", I assume this is the amount of domains (list downloads and upstream urls) which the bootstrap resolver are currently handling. I deactivated metrics in bootstrap, it should work as expected now

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
🐞 bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants