Very slow response from upstream servers with a lot of `context deadline exceeded`

### Prerequisites

- [X] I have checked the [Wiki](https://github.com/AdguardTeam/AdGuardHome/wiki) and [Discussions](https://github.com/AdguardTeam/AdGuardHome/discussions/categories/q-a) 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](https://github.com/AdguardTeam/AdGuardHome/discussions/categories/q-a)

- [X] I have set up AdGuard Home correctly and [configured clients to use it](https://github.com/AdguardTeam/AdGuardHome/wiki/Clients). (Use the [Discussions](https://github.com/AdguardTeam/AdGuardHome/discussions/categories/q-a) for help with installing and configuring clients.)


### Platform (OS and CPU architecture)

Linux, ARM64

Raspberry Pi 4

```sh
sukka@sukka-pi:/tmp $ uname -a
Linux sukka-pi 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux
```

### Installation

GitHub releases or script from README

### Setup

On one machine

### AdGuard Home version

v0.107.53

### Action

Replace the following command with the one you're calling or a
description of the failing action:

```sh
nslookup -debug -type=a 'www.example.com' '127.0.0.1'
dig www.example.com @127.0.0.1
```



### Expected result

The result returned immdiately.

### Actual result

The result returned in about 20 seconds.

### Additional information and/or screenshots

I have set following upstream servers in the `DNS settings`:

```
https://120.53.53.53/dns-query
https://1.12.12.12/dns-query
tls://120.53.53.53
tls://1.12.12.12
```

But when I use the `Test upstreams` button, AdGuardHome says all those servers could not be used:

<img width="355" alt="image" src="https://github.com/user-attachments/assets/768cf721-438f-4f6d-8ea3-4bba36ce5c51">

I have tested those servers locally, they return the result very fast, so definitely no internet connectivity issue, and also there is no problem with the upstream servers:

```
sukka@sukka-pi:/tmp $ time dig www.example.com @120.53.53.53 +https +short
93.184.215.14

real    0m0.342s
user    0m0.060s
sys     0m0.014s
sukka@sukka-pi:/tmp $ time dig www.example.com @120.53.53.53 +tls +short
93.184.215.14

real    0m0.250s
user    0m0.054s
sys     0m0.025s
sukka@sukka-pi:/tmp $ time dig www.example.com @1.12.12.12 +https +short
93.184.215.14

real    0m0.128s
user    0m0.056s
sys     0m0.024s
sukka@sukka-pi:/tmp $ time dig www.example.com @1.12.12.12 +tls +short
93.184.215.14

real    0m0.185s
user    0m0.059s
sys     0m0.020s
```

I have also tried with `curl`:

```
sukka@sukka-pi:/tmp $ time curl https://120.53.53.53/dns-query

real    0m0.212s
user    0m0.147s
sys     0m0.025s

sukka@sukka-pi:/tmp $ time curl https://1.12.12.12/dns-query

real    0m0.214s
user    0m0.149s
sys     0m0.016s
```

I then enabled `log.verbose` in the config file (`AdGuardHome.yaml`), and I got those logs:

```
2024/10/18 22:29:36.482822 1090#350 [error] dnsproxy: exchange failed upstream=tls://1.12.12.12:853 question=";www.example.com.\tIN\t A" duration=10.011039607s err="getting conn to tls://1.12.12.12:853: connecting to 1.12.12.12: read tcp 10.10.1.200:60174->1.12.12.12:853: i/o timeout"
2024/10/18 22:29:38.492967 1090#485 [debug] started GET 10.10.1.200:11451 /control/status
2024/10/18 22:29:38.494299 1090#485 [debug] finished GET 10.10.1.200:11451 /control/status in 1.363265ms
2024/10/18 22:29:46.495655 1090#350 [error] dnsproxy: exchange failed upstream=tls://120.53.53.53:853 question=";www.example.com.\tIN\t A" duration=10.012209931s err="getting conn to tls://120.53.53.53:853: connecting to 120.53.53.53: read tcp 10.10.1.200:40744->120.53.53.53:853: i/o timeout"
2024/10/18 22:29:46.496177 1090#350 [debug] dnsproxy: resolving err src=upstream err="all upstreams failed to exchange request: requesting https://120.53.53.53:443/dns-query: Get \"https://120.53.53.53:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwdleGFtcGxlA2NvbQAAAQABAAApCAAAAIAAAAA\": context deadline exceeded\nrequesting https://1.12.12.12:443/dns-query: Get \"https://1.12.12.12:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwdleGFtcGxlA2NvbQAAAQABAAApCAAAAIAAAAA\": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)\ngetting conn to tls://1.12.12.12:853: connecting to 1.12.12.12: read tcp 10.10.1.200:60174->1.12.12.12:853: i/o timeout\ngetting conn to tls://120.53.53.53:853: connecting to 120.53.53.53: read tcp 10.10.1.200:40744->120.53.53.53:853: i/o timeout"
2024/10/18 22:29:46.496360 1090#350 [debug] dnsforward: finished processing upstream
2024/10/18 22:29:46.496644 1090#350 [debug] dnsproxy: out line_num=1 line=";; opcode: QUERY, status: SERVFAIL, id: 32875"
2024/10/18 22:29:46.496905 1090#350 [debug] dnsproxy: out line_num=2 line=";; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0"
2024/10/18 22:29:46.497117 1090#350 [debug] dnsproxy: out line_num=3 line=""
2024/10/18 22:29:46.497331 1090#350 [debug] dnsproxy: out line_num=4 line=";; QUESTION SECTION:"
2024/10/18 22:29:46.497545 1090#350 [debug] dnsproxy: out line_num=5 line=";www.example.com.\tIN\t A"
2024/10/18 22:29:46.497752 1090#350 [debug] dnsproxy: out line_num=6 line=""
2024/10/18 22:29:46.498229 1090#350 [debug] dnsproxy: handling dns request proto=udp err="using request handler: all upstreams failed to exchange request: requesting https://120.53.53.53:443/dns-query: Get \"https://120.53.53.53:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwdleGFtcGxlA2NvbQAAAQABAAApCAAAAIAAAAA\": context deadline exceeded\nrequesting https://1.12.12.12:443/dns-query: Get \"https://1.12.12.12:443/dns-query?dns=AAABAAABAAAAAAABA3d3dwdleGFtcGxlA2NvbQAAAQABAAApCAAAAIAAAAA\": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)\ngetting conn to tls://1.12.12.12:853: connecting to 1.12.12.12: read tcp 10.10.1.200:60174->1.12.12.12:853: i/o timeout\ngetting conn to tls://120.53.53.53:853: connecting to 120.53.53.53: read tcp 10.10.1.200:40744->120.53.53.53:853: i/o timeout"
2024/10/18 22:32:17.276231 1090#486 [debug] started GET 10.10.1.200:11451 /control/status
2024/10/18 22:32:17.277575 1090#486 [debug] finished GET 10.10.1.200:11451 /control/status in 1.398173ms
2024/10/18 22:32:19.917784 1090#486 [debug] started POST 10.10.1.200:11451 /control/test_upstream_dns
2024/10/18 22:32:29.919010 ERROR response received addr=https://1.12.12.12:443/dns-query proto=tcp status="requesting https://1.12.12.12:443/dns-query: Get \"https://1.12.12.12:443/dns-query?dns=AAABAAABAAAAAAAABHRlc3QAAAEAAQ\": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)"
2024/10/18 22:32:29.919133 ERROR response received addr=https://120.53.53.53:443/dns-query proto=tcp status="requesting https://120.53.53.53:443/dns-query: Get \"https://120.53.53.53:443/dns-query?dns=AAABAAABAAAAAAAABHRlc3QAAAEAAQ\": context deadline exceeded"
2024/10/18 22:32:29.933972 1090#486 [debug] finished POST 10.10.1.200:11451 /control/test_upstream_dns in 10.016169079s
2024/10/18 22:32:48.354208 1090#486 [debug] started GET 10.10.1.200:11451 /control/status
2024/10/18 22:32:48.355457 1090#486 [debug] finished GET 10.10.1.200:11451 /control/status in 1.294076ms
2024/10/18 22:34:47.290447 1090#554 [debug] started GET 10.10.1.200:11451 /control/status
2024/10/18 22:34:47.291737 1090#554 [debug] finished GET 10.10.1.200:11451 /control/status in 1.338358ms
2024/10/18 22:34:48.408058 1090#554 [debug] started POST 10.10.1.200:11451 /control/test_upstream_dns
2024/10/18 22:34:58.409273 ERROR response received addr=https://120.53.53.53:443/dns-query proto=tcp status="requesting https://120.53.53.53:443/dns-query: Get \"https://120.53.53.53:443/dns-query?dns=AAABAAABAAAAAAAABHRlc3QAAAEAAQ\": context deadline exceeded"
2024/10/18 22:34:58.409278 ERROR response received addr=https://1.12.12.12:443/dns-query proto=tcp status="requesting https://1.12.12.12:443/dns-query: Get \"https://1.12.12.12:443/dns-query?dns=AAABAAABAAAAAAAABHRlc3QAAAEAAQ\": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)"
2024/10/18 22:34:58.445246 1090#554 [debug] finished POST 10.10.1.200:11451 /control/test_upstream_dns in 10.037199239s
```

Also average upstream servers response time:

<img width="607" alt="image" src="https://github.com/user-attachments/assets/b05d41d5-5318-4aa1-af39-bc475bcbdacb">

So somehow AdGuardHome failed to connect to upstream servers while `dig` works just fine.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Very slow response from upstream servers with a lot of `context deadline exceeded` #7357

Prerequisites

Platform (OS and CPU architecture)

Installation

Setup

AdGuard Home version

Action

Expected result

Actual result

Additional information and/or screenshots

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Very slow response from upstream servers with a lot of context deadline exceeded #7357

Description

Prerequisites

Platform (OS and CPU architecture)

Installation

Setup

AdGuard Home version

Action

Expected result

Actual result

Additional information and/or screenshots

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Very slow response from upstream servers with a lot of `context deadline exceeded` #7357