Log bootstrap/upstream timeouts on ERROR level, not DEBUG

adoyle-h commented 10 months ago

Prerequisites

[X] I have checked the Wiki and Discussions and found no answer
[X] I have searched other issues and found no duplicates
[X] I want to report a bug and not ask a question or ask for help
[X] I have set up AdGuard Home correctly and configured clients to use it. (Use the Discussions for help with installing and configuring clients.)

Platform (OS and CPU architecture)

Linux, AMD64 (aka x86_64)

Installation

Docker

Setup

On one machine

AdGuard Home version

v0.107.43 and v0.108.0-b.51

Action

The docker compose.yaml

version: "3.9"

services:
  adg:
    # image: adguard/adguardhome:v0.108.0-b.51
    image: adguard/adguardhome:v0.107.43
    restart: unless-stopped
    volumes:
      - ./work:/opt/adguardhome/work
      - ./conf:/opt/adguardhome/conf
      - ./.lego/certificates:/opt/adguardhome/cert
    mac_address: F8:7D:36:12:11:FB
    networks:
      macvlan:
        ipv4_address: 192.168.1.61

networks:
  macvlan:
    driver: macvlan
    driver_opts:
      parent: enp1s0

    ipam:
      config:
        - subnet: "192.168.1.0/24"
          ip_range: "192.168.1.61/30"
          gateway: "192.168.1.2"

The ./conf/AdGuardHome.yaml

http:
  pprof:
    port: 6060
    enabled: false
  address: 0.0.0.0:80
  session_ttl: 4h
auth_attempts: 5
block_auth_min: 15
http_proxy: ""
language: en
theme: auto
dns:
  bind_hosts:
    - 0.0.0.0
  port: 53
  anonymize_client_ip: false
  ratelimit: 20
  ratelimit_subnet_len_ipv4: 24
  ratelimit_subnet_len_ipv6: 56
  ratelimit_whitelist: []
  refuse_any: true
  upstream_dns:
    - https://dns10.quad9.net/dns-query
  upstream_dns_file: /opt/adguardhome/conf/dns.rules
  bootstrap_dns:
    - tls://223.5.5.5
  fallback_dns:
    - https://1.1.1.1/dns-query
  all_servers: true
  fastest_addr: false
  fastest_timeout: 1s
  allowed_clients: []
  disallowed_clients: []
  blocked_hosts:
    - version.bind
    - id.server
    - hostname.bind
  trusted_proxies:
    - 127.0.0.0/8
    - ::1/128
  cache_size: 67108864
  cache_ttl_min: 600
  cache_ttl_max: 800
  cache_optimistic: false
  bogus_nxdomain: []
  aaaa_disabled: false
  enable_dnssec: false
  edns_client_subnet:
    custom_ip: ""
    enabled: false
    use_custom: false
  max_goroutines: 300
  handle_ddr: true
  ipset: []
  ipset_file: ""
  bootstrap_prefer_ipv6: false
  upstream_timeout: 10s
  private_networks: []
  use_private_ptr_resolvers: true
  local_ptr_upstreams: []
  use_dns64: false
  dns64_prefixes: []
  serve_http3: false
  use_http3_upstreams: false
  serve_plain_dns: true
tls:
  enabled: false
querylog:
  ignored: []
  interval: 168h
  size_memory: 1000
  enabled: true
  file_enabled: true
statistics:
  ignored: []
  interval: 720h
  enabled: true
filters: []
whitelist_filters: []
user_rules:
  - '@@||s.deepl.com^$important'
  - ""
dhcp:
  enabled: false
filtering:
  blocking_ipv4: ""
  blocking_ipv6: ""
  blocked_services:
    schedule:
      time_zone: UTC
    ids: []
  protection_disabled_until: null
  safe_search:
    enabled: false
    bing: true
    duckduckgo: true
    google: true
    pixabay: true
    yandex: true
    youtube: true
  blocking_mode: default
  parental_block_host: family-block.dns.adguard.com
  safebrowsing_block_host: standard-block.dns.adguard.com
  rewrites: []
  safebrowsing_cache_size: 1048576
  safesearch_cache_size: 1048576
  parental_cache_size: 1048576
  cache_time: 30
  filters_update_interval: 24
  blocked_response_ttl: 10
  filtering_enabled: true
  parental_enabled: false
  safebrowsing_enabled: false
  protection_enabled: true
clients:
  runtime_sources:
    whois: true
    arp: true
    rdns: true
    dhcp: true
    hosts: true
  persistent: []
log:
  file: ""
  max_backups: 0
  max_size: 100
  max_age: 3
  compress: false
  local_time: false
  verbose: false
os:
  group: ""
  user: ""
  rlimit_nofile: 0
schema_version: 27

The ./conf/dns.rules

https://doh.dns.sb/dns-query
[/ipip.net/]tls://223.5.5.5

docker compose up -d
Send DNS request

nslookup -debug -type=a 'www.baidu.com'

Expected result

The query log shows DNS server using https://doh.dns.sb/dns-query.

Actual result

It seems the default upstream (https://doh.dns.sb/dns-query) is ignored in upstream_dns_file. All DNS queries use the fallback_dns (https://1.1.1.1:443/dns-query).

CleanShot 2023-12-22 at 21 00 48@2x

The query log shows that adguard home using the DNS server https://1.1.1.1:443/dns-query which is my fallback_dns.

But when nslookup www.ipip.net, which domain defined in upstream_dns_file, the query log shows the DNS server using tls://223.5.5.5:853.

> nslookup www.ipip.net
Server:         192.168.1.61
Address:        192.168.1.61#53

Non-authoritative answer:
www.ipip.net    canonical name = 8d2070e4.ipip.net.cname.yunduns.com.
Name:   8d2070e4.ipip.net.cname.yunduns.com
Address: 220.185.183.49
Name:   8d2070e4.ipip.net.cname.yunduns.com
Address: 220.185.183.30

CleanShot 2023-12-22 at 21 14 01@2x

Additional information and/or screenshots

There is no https://doh.dns.sb/dns-query in top upstreams.

CleanShot 2023-12-22 at 21 16 21@2x

adoyle-h commented 10 months ago

After enable verbose logs. It shows the requests to doh.dns.sb always timeout.

> nslookup doh.dns.sb 223.5.5.5
Server:         223.5.5.5
Address:        223.5.5.5#53

Non-authoritative answer:
doh.dns.sb      canonical name = asia.doh.sb.
asia.doh.sb     canonical name = jp-nrt.doh.sb.
Name:   jp-nrt.doh.sb
Address: 103.121.210.210
Name:   jp-nrt.doh.sb
Address: 2403:fbc0:1000::babe

Container Logs:

2023/12/23 07:50:27.899050 1#687 [debug] dnsproxy: https://doh.dns.sb:443/dns-query: response received over tcp: "requesting https://do
h.dns.sb:443/dns-query: Get \"https://doh.dns.sb:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwZub3Rpb24Cc28AAAEAAQAAKQgAAACAAAAA\": net/http
: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)"
2023/12/23 07:50:27.899054 1#647 [debug] bootstrap: connection to 103.121.210.210:443 failed in 6.383582033s: dial tcp 103.121.210.210:
443: i/o timeout
2023/12/23 07:50:27.899203 1#687 [debug] re-creating the http client due to requesting https://doh.dns.sb:443/dns-query: Get "https://d
oh.dns.sb:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwZub3Rpb24Cc28AAAEAAQAAKQgAAACAAAAA": net/http: request canceled while waiting for con
nection (Client.Timeout exceeded while awaiting headers)
2023/12/23 07:50:27.899388 1#647 [debug] bootstrap: dialing [2403:fbc0:1000::babe]:443 (2/2)
2023/12/23 07:50:27.899537 1#647 [debug] bootstrap: connection to [2403:fbc0:1000::babe]:443 failed in 27.841µs: dial tcp [2403:fbc0:10
00::babe]:443: i/o timeout
2023/12/23 07:50:27.899567 1#687 [debug] using HTTP/2 for this upstream: HTTP3 support is not enabled
2023/12/23 07:50:27.899713 1#687 [debug] dnsproxy: https://doh.dns.sb:443/dns-query: sending request over tcp: A www.notion.so.
2023/12/23 07:50:27.899940 1#699 [debug] bootstrap: dialing 103.121.210.210:443 (1/2)
2023/12/23 07:50:31.515756 1#8 [debug] dnsproxy: https://doh.dns.sb:443/dns-query: response received over tcp: "requesting https://doh.dns.sb:443/dns-query: Get \"https://doh.dns.sb:443/dns-query?dns=AAABAAABAAAAAAABATMBYQFiAWEBMQE5ATYBMwEyAWQBMQFhATQBYgExATcBMAE1ATMBMQ
E3ATABOAEwATABOQEzATABZQEwATQBMgNpcDYEYXJwYQAADAABAAApCAAAAIAAAAA\": net/http: request canceled while waiting for connection (Client.Ti
meout exceeded while awaiting headers)"
2023/12/23 07:50:31.515907 1#8 [debug] re-creating the http client due to requesting https://doh.dns.sb:443/dns-query: Get "https://doh
.dns.sb:443/dns-query?dns=AAABAAABAAAAAAABATMBYQFiAWEBMQE5ATYBMwEyAWQBMQFhATQBYgExATcBMAE1ATMBMQE3ATABOAEwATABOQEzATABZQEwATQBMgNpcDYEY
XJwYQAADAABAAApCAAAAIAAAAA": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2023/12/23 07:50:31.515936 1#692 [debug] bootstrap: connection to 103.121.210.210:443 failed in 10.000411633s: dial tcp 103.121.210.210
:443: operation was canceled
2023/12/23 07:50:31.515999 1#692 [debug] bootstrap: dialing [2403:fbc0:1000::babe]:443 (2/2)

ping 103.121.210.210 is successful in container.

> docker exec -it adguard-home-adg-1 ping 103.121.210.210
PING 103.121.210.210 (103.121.210.210): 56 data bytes
64 bytes from 103.121.210.210: seq=0 ttl=48 time=50.335 ms
64 bytes from 103.121.210.210: seq=1 ttl=48 time=53.179 ms
64 bytes from 103.121.210.210: seq=2 ttl=48 time=47.453 ms
64 bytes from 103.121.210.210: seq=3 ttl=48 time=48.489 ms
64 bytes from 103.121.210.210: seq=4 ttl=48 time=41.199 ms
64 bytes from 103.121.210.210: seq=5 ttl=48 time=46.852 ms
^C
--- 103.121.210.210 ping statistics ---
6 packets transmitted, 6 packets received, 0% packet loss
round-trip min/avg/max = 41.199/47.917/53.179 ms

adoyle-h commented 10 months ago

I found the reason. The DoH https://doh.dns.sb/dns-query is blocked by GFW in China. The upstream is inaccessible. So AdGuard Home use fallback_dns.

I think the logs of timeout requests to upstream should be WARN or ERROR level, not the DEBUG level.

EugeneOne1 commented 10 months ago

@adoyle-h, hello again. We've changed the logging level in the latest edge release and will include it to the upcoming releases. We'll close the issue for now. Feel free to reopen it if the log message won't appear informative enough.

AdguardTeam / AdGuardHome