AdGuardHome 0.107.2 error in handling tcp: reading msg: reading len: read tcp: i/o timeout #4128

grzesiczek1 · 2022-01-12T13:15:10Z

Issue Details

Version of AdGuard Home server:
- v0.107.2
How did you install AdGuard Home:
- Docker
How did you setup DNS configuration:
- System
If it's a router or IoT, please write device model:
- Raspberry Pi 4
CPU architecture:
- ARM
Operating system and version:
- Raspbian 11

Expected Behavior

No error in the error log

Actual Behavior

Error log flooded with following events:
2022/01/12 04:30:06.582567 [error] handling tcp: reading msg: reading len: read tcp x.x.x.x:853->x.x.x.x:36114: i/o timeout

Screenshots

Screenshot:

Additional Information

seanob86 · 2022-01-12T22:21:40Z

I too have the same error events in similar setup as OP. AdGuard Home 0.107.2 in docker container. Appears events only occur while clients are connecting via DoT to the server.

sturmstar · 2022-01-13T12:08:06Z

I observed exactly the same - only when clients connecting via DoT

grzesiczek1 · 2022-01-13T14:45:56Z

I can add that this is visible for both IPv4 and IPv6 addresses with exactly same output.

ainar-g · 2022-01-19T14:13:54Z

Hello. Those looks like either the client connection was improperly closed or the client just didn't respond.

@ameshkov, how about hiding timeout errors from dnsproxy behind the debug level?

sturmstar · 2022-01-19T14:36:48Z

Hi. In my case DoT is fully working (for the client) - it's just the anoying log

grzesiczek1 · 2022-01-19T16:13:09Z

Hi. In my case DoT is fully working (for the client) - it's just the anoying log

Agree, there is nothing that does not work (or I did not notice) - all DNS resolutions working fine just logs are flooded.

Updates AdguardTeam/AdGuardHome#4128. Squashed commit of the following: commit f3f7044 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Thu Jan 20 16:49:59 2022 +0300 proxy: imp err handling

Updates #4128. Squashed commit of the following: commit c177750 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Thu Jan 20 17:01:02 2022 +0300 all: upd dnsproxy

ainar-g · 2022-01-20T14:53:28Z

@grzesiczek1, @sturmstar, the newest release on the edge channel should include the fix for the issue. Could you please check if the error messages are gone for you? Thanks.

sturmstar · 2022-01-21T05:57:02Z

Hi! Issue is gone with edge channel - perfect - thank you very much

zbulb · 2022-02-05T12:36:45Z

Encountered this issue in v0.107.3

Feb 5 15:17:55 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:17:40.849763 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: read tcp [WAN IPV4]:59031->1.0.0.2:853: i/o timeout
Feb 5 15:19:13 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:18:35.030329 [info] responding to udp request: writing message: write udp [::]:53->192.168.1.181:60777: i/o timeout
Feb 5 15:19:36 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:19:36.528230 [info] responding to udp request: writing message: write udp [::]:53->192.168.1.161:49293: i/o timeout
Feb 5 15:20:15 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:20:12.105887 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: write tcp [WAN IPV4]:46889->1.1.1.2:853: i/o timeout
Feb 5 15:21:22 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:21:22.588635 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: read tcp [WAN IPV4]:59408->1.0.0.2:853: i/o timeout
Feb 5 15:21:43 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:21:43.979173 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: read tcp [WAN IPV4]:59361->1.0.0.2:853: i/o timeout
Feb 5 15:22:25 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:22:25.647789 [info] responding to udp request: writing message: write udp [::]:53->192.168.1.135:51080: i/o timeout
Feb 5 15:22:59 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:22:27.994767 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: read tcp [WAN IPV6]:34903->[2606:4700:4700::1002]:853: i/o timeout
Feb 5 15:23:58 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:23:48.231218 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: write tcp [WAN IPV4]:59151->1.0.0.2:853: i/o timeout
Feb 5 15:23:58 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:23:49.776286 [error] handling tcp: handling tcp request: talking to dns upstream: getting connection to tls://security.cloudflare-dns.com:853: connecting to security.cloudflare-dns.com: read tcp [WAN IPV4]:47523->1.1.1.2:853: i/o timeout
Feb 5 15:23:58 RT-AC86U-7510 AdGuardHome[31767]: 2022/02/05 15:23:51.417432 [info] responding to udp request: writing message: write udp [::]:53->[fe80::a2c:2664:1e49:9711%br0]:56501: i/o timeout

ainar-g · 2022-02-09T12:06:37Z

@zbulb, thanks for the info! We'll fix it in v0.107.4.

Updates AdguardTeam/AdGuardHome#4128. Squashed commit of the following: commit 9211b05 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Tue Feb 15 16:28:23 2022 +0300 proxy: imp timeout logs

dnomd343 · 2022-10-04T11:38:38Z

This problem still seems to exist in v0.107.14 of docker environment.

ameshkov · 2022-10-04T11:41:43Z

@dnomd343 this one seems different, it cannot verify the upstream certificate.

dnomd343 · 2022-10-04T11:48:26Z

My AdGuardHome is running on the intranet, its upstream is not DoT or DoH, I suspect the problem comes from the enabled DoH service.

bind_host: 0.0.0.0
bind_port: 80
beta_bind_port: 0
users:
  - name: dnomd343
    password: ...
auth_attempts: 5
block_auth_min: 15
http_proxy: ""
language: zh-cn
debug_pprof: false
web_session_ttl: 720
dns:
  bind_hosts:
    - 0.0.0.0
  port: 53
  statistics_interval: 30
  querylog_enabled: true
  querylog_file_enabled: true
  querylog_interval: 720h
  querylog_size_memory: 1000
  anonymize_client_ip: false
  protection_enabled: true
  blocking_mode: default
  blocking_ipv4: ""
  blocking_ipv6: ""
  blocked_response_ttl: 10
  parental_block_host: family-block.dns.adguard.com
  safebrowsing_block_host: standard-block.dns.adguard.com
  ratelimit: 0
  ratelimit_whitelist: []
  refuse_any: true
  upstream_dns:
    - 127.0.0.1:5353
  upstream_dns_file: ""
  bootstrap_dns:
    - 9.9.9.10
    - 149.112.112.10
    - 2620:fe::10
    - 2620:fe::fe:10
  all_servers: false
  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: 16777216
  cache_ttl_min: 60
  cache_ttl_max: 518400
  cache_optimistic: true
  bogus_nxdomain: []
  aaaa_disabled: false
  enable_dnssec: true
  edns_client_subnet: false
  max_goroutines: 300
  handle_ddr: true
  ipset: []
  ipset_file: ""
  filtering_enabled: true
  filters_update_interval: 24
  parental_enabled: false
  safesearch_enabled: false
  safebrowsing_enabled: false
  safebrowsing_cache_size: 1048576
  safesearch_cache_size: 1048576
  parental_cache_size: 1048576
  cache_time: 30
  rewrites:
    - domain: dns.343.re
      answer: 8.210.148.24
    - domain: dns.scutbot.cn
      answer: 106.55.62.186
    - domain: dns.scutrobot.com
      answer: 119.28.88.230
    - domain: nps.dnomd343.top
      answer: 8.210.148.24
    - domain: '*.scut.343.re'
      answer: 192.168.2.34
    - domain: dns.scut.343.re
      answer: 192.168.2.3
  blocked_services: []
  upstream_timeout: 10s
  private_networks: []
  use_private_ptr_resolvers: true
  local_ptr_upstreams: []
tls:
  enabled: true
  server_name: dns.scut.343.re
  force_https: false
  port_https: 443
  port_dns_over_tls: 853
  port_dns_over_quic: 784
  port_dnscrypt: 0
  dnscrypt_config_file: ""
  allow_unencrypted_doh: false
  strict_sni_check: false
  certificate_chain: ""
  private_key: ""
  certificate_path: /etc/ssl/certs/scut.343.re/fullchain.pem
  private_key_path: /etc/ssl/certs/scut.343.re/privkey.pem
filters:
  - enabled: true
    url: https://res.343.re/Share/Adblock-Rules/xinggsf.txt
    name: 乘风规则
    id: 1646875485
  - enabled: true
    url: https://adaway.org/hosts.txt
    name: AdAway
    id: 1646875486
  - enabled: true
    url: https://adguardteam.github.io/AdGuardSDNSFilter/Filters/filter.txt
    name: AdGuard
    id: 1646875487
  - enabled: true
    url: https://anti-ad.net/easylist.txt
    name: Anti AD
    id: 1646875488
whitelist_filters: []
user_rules:
  - ""
dhcp:
  enabled: false
  interface_name: ""
  local_domain_name: lan
  dhcpv4:
    gateway_ip: ""
    subnet_mask: ""
    range_start: ""
    range_end: ""
    lease_duration: 86400
    icmp_timeout_msec: 1000
    options: []
  dhcpv6:
    range_start: ""
    lease_duration: 86400
    ra_slaac_only: false
    ra_allow_slaac: false
clients:
  runtime_sources:
    whois: true
    arp: true
    rdns: true
    dhcp: true
    hosts: true
  persistent: []
log_file: ""
log_max_backups: 0
log_max_size: 100
log_max_age: 3
log_compress: false
log_localtime: false
verbose: false
os:
  group: ""
  user: ""
  rlimit_nofile: 0
schema_version: 14

I will try to turn off the external encrypted DNS service and see if the problem still occurs.

ameshkov · 2022-10-04T12:07:49Z

It's also possible that some client tries to connect to your resolver via TLS and fails to verify your certificate.

dnomd343 · 2022-10-09T17:17:29Z

Through the monitoring of the following command, I got the tcpdump packet capture data that caused this error:

tcpdump '(dst host 192.168.2.3) and ((dst port 443) or (dst port 853))' -n -vv

···
01:02:37.876186 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [.], cksum 0x6d10 (correct), seq 719467082, ack 2189841556, win 2058, options [nop,nop,TS val 3973646366 ecr 2422394318], length 0
01:02:37.876323 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [P.], cksum 0xe83c (correct), seq 0:517, ack 1, win 2058, options [nop,nop,TS val 3973646366 ecr 2422394318], length 517
01:02:37.890868 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [.], cksum 0x588f (correct), seq 517, ack 4714, win 2048, options [nop,nop,TS val 3973646381 ecr 2422394332], length 0
01:02:37.910490 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 82)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [P.], cksum 0x3ae6 (correct), seq 517:547, ack 4714, win 2048, options [nop,nop,TS val 3973646402 ecr 2422394332], length 30
01:02:37.911740 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [F.], cksum 0x585b (correct), seq 547, ack 4714, win 2048, options [nop,nop,TS val 3973646402 ecr 2422394332], length 0
01:02:37.913506 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61700 > 192.168.2.3.853: Flags [F.], cksum 0x583e (correct), seq 547, ack 4715, win 2048, options [nop,nop,TS val 3973646405 ecr 2422394357], length 0
···
01:12:11.042054 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [SEW], cksum 0xd320 (correct), seq 4036225739, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 3307620750 ecr 0,sackOK,eol], length 0
01:12:11.042226 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [S], cksum 0xd379 (correct), seq 4036225739, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 3307620853 ecr 0,sackOK,eol], length 0
01:12:11.042226 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [S], cksum 0xd314 (correct), seq 4036225739, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 3307620954 ecr 0,sackOK,eol], length 0
01:12:11.051143 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [P.], cksum 0x6c42 (correct), seq 4036225740:4036226257, ack 4184404303, win 2058, options [nop,nop,TS val 3307621018 ecr 2422967488], length 517
01:12:11.051327 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [.], cksum 0x00a1 (correct), seq 517, ack 1, win 2058, options [nop,nop,TS val 3307621018 ecr 2422967488], length 0
01:12:11.066375 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [.], cksum 0xee17 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 3307621033 ecr 2422967506], length 0
01:12:11.082562 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [F.], cksum 0xee04 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 3307621051 ecr 2422967506], length 0
01:12:11.089833 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.61817 > 192.168.2.3.443: Flags [SEW], cksum 0x5952 (correct), seq 2050287566, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 2251652003 ecr 0,sackOK,eol], length 0
01:12:11.090089 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61810 > 192.168.2.3.443: Flags [.], cksum 0xede9 (correct), seq 518, ack 4724, win 2048, options [nop,nop,TS val 3307621054 ecr 2422967529], length 0
01:12:11.093345 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.61817 > 192.168.2.3.443: Flags [P.], cksum 0x5322 (correct), seq 2050287567:2050288084, ack 2440560720, win 2058, options [nop,nop,TS val 2251652011 ecr 2422967536], length 517
01:12:11.108775 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61817 > 192.168.2.3.443: Flags [.], cksum 0xce11 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 2251652027 ecr 2422967549], length 0
01:12:11.117232 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61817 > 192.168.2.3.443: Flags [F.], cksum 0xce07 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 2251652036 ecr 2422967549], length 0
01:12:11.120371 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.61819 > 192.168.2.3.443: Flags [SEW], cksum 0x9608 (correct), seq 3427821745, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 3554614850 ecr 0,sackOK,eol], length 0
01:12:11.120500 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.61817 > 192.168.2.3.443: Flags [.], cksum 0xcdf4 (correct), seq 518, ack 4724, win 2048, options [nop,nop,TS val 2251652040 ecr 2422967563], length 0
···

These data are from an iPad Pro 2022, but this does not happen to the iPad Air 4 and iPad 2021 under the same network. The target you are trying to access is DoH and DoT, I suspect this is a problem with an app rather than iPadOS.

I will track the access target in debug mode later.

dnomd343 · 2022-10-09T17:28:30Z

Logs from AdGuardHome:

2022/10/10 01:22:51.143449 5649#81 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).handleTCPConnection(): handling tcp: started handling tls request from 192.168.2.133:62136
2022/10/10 01:22:51.177808 5649#81 [error] handling tcp: reading msg: reading len: remote error: tls: bad certificate
2022/10/10 01:22:51.185755 5649#82 [debug] web: https: http: TLS handshake error from 192.168.2.133:62137: EOF
2022/10/10 01:22:51.213607 5649#58 [debug] web: https: http: TLS handshake error from 192.168.2.133:62139: EOF
2022/10/10 01:23:21.352240 5649#59 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).handleTCPConnection(): handling tcp: started handling tls request from 192.168.2.133:62142
2022/10/10 01:23:21.383105 5649#59 [error] handling tcp: reading msg: reading len: remote error: tls: bad certificate

Output of tcpdump:

01:22:51.138374 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [SEW], cksum 0x05fa (correct), seq 3836259429, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 2528021662 ecr 0,sackOK,eol], length 0
01:22:51.138534 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.62137 > 192.168.2.3.443: Flags [SEW], cksum 0x0cbc (correct), seq 3160268472, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 1386725748 ecr 0,sackOK,eol], length 0
01:22:51.142827 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [.], cksum 0x64ff (correct), seq 3836259430, ack 4258068997, win 2058, options [nop,nop,TS val 2528021670 ecr 2423607584], length 0
01:22:51.142970 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [P.], cksum 0x7a46 (correct), seq 0:517, ack 1, win 2058, options [nop,nop,TS val 2528021670 ecr 2423607584], length 517
01:22:51.143200 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.62137 > 192.168.2.3.443: Flags [P.], cksum 0x3bf6 (correct), seq 3160268473:3160268990, ack 3058451455, win 2058, options [nop,nop,TS val 1386725753 ecr 2423607584], length 517
01:22:51.159408 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62137 > 192.168.2.3.443: Flags [.], cksum 0x54bf (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 1386725769 ecr 2423607599], length 0
01:22:51.160981 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [.], cksum 0x5078 (correct), seq 517, ack 4714, win 2048, options [nop,nop,TS val 2528021688 ecr 2423607601], length 0
01:22:51.177540 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 82)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [P.], cksum 0x4ebe (correct), seq 517:547, ack 4714, win 2048, options [nop,nop,TS val 2528021706 ecr 2423607601], length 30
01:22:51.178906 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [F.], cksum 0x5047 (correct), seq 547, ack 4714, win 2048, options [nop,nop,TS val 2528021706 ecr 2423607601], length 0
01:22:51.180909 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62136 > 192.168.2.3.853: Flags [F.], cksum 0x502c (correct), seq 547, ack 4715, win 2048, options [nop,nop,TS val 2528021709 ecr 2423607624], length 0
01:22:51.185524 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62137 > 192.168.2.3.443: Flags [F.], cksum 0x54a2 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 1386725797 ecr 2423607599], length 0
01:22:51.187561 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.62139 > 192.168.2.3.443: Flags [SEW], cksum 0x4b64 (correct), seq 3978336160, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 3687976948 ecr 0,sackOK,eol], length 0
01:22:51.189981 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62137 > 192.168.2.3.443: Flags [.], cksum 0x547d (correct), seq 518, ack 4724, win 2048, options [nop,nop,TS val 1386725800 ecr 2423607632], length 0
01:22:51.190810 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.62139 > 192.168.2.3.443: Flags [P.], cksum 0xd7bd (correct), seq 3978336161:3978336678, ack 17192272, win 2058, options [nop,nop,TS val 3687976952 ecr 2423607634], length 517
01:22:51.205457 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62139 > 192.168.2.3.443: Flags [.], cksum 0x3732 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 3687976966 ecr 2423607645], length 0
01:22:51.213413 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62139 > 192.168.2.3.443: Flags [F.], cksum 0x3728 (correct), seq 517, ack 4723, win 2048, options [nop,nop,TS val 3687976975 ecr 2423607645], length 0
01:22:51.216688 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62139 > 192.168.2.3.443: Flags [.], cksum 0x3715 (correct), seq 518, ack 4724, win 2048, options [nop,nop,TS val 3687976978 ecr 2423607660], length 0
01:23:21.347672 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 64)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [SEW], cksum 0x3be7 (correct), seq 296819392, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 2281294333 ecr 0,sackOK,eol], length 0
01:23:21.351799 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [.], cksum 0x9384 (correct), seq 296819393, ack 1213481190, win 2058, options [nop,nop,TS val 2281294339 ecr 2423637794], length 0
01:23:21.351880 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 569)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [P.], cksum 0xe4f3 (correct), seq 0:517, ack 1, win 2058, options [nop,nop,TS val 2281294339 ecr 2423637794], length 517
01:23:21.366943 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [.], cksum 0x7f05 (correct), seq 517, ack 4714, win 2048, options [nop,nop,TS val 2281294353 ecr 2423637807], length 0
01:23:21.382897 IP (tos 0x2,ECT(0), ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 82)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [P.], cksum 0x6bf6 (correct), seq 517:547, ack 4714, win 2048, options [nop,nop,TS val 2281294371 ecr 2423637807], length 30
01:23:21.383363 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [F.], cksum 0x7ed4 (correct), seq 547, ack 4714, win 2048, options [nop,nop,TS val 2281294371 ecr 2423637807], length 0
01:23:21.386138 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.2.133.62142 > 192.168.2.3.853: Flags [F.], cksum 0x7eba (correct), seq 547, ack 4715, win 2048, options [nop,nop,TS val 2281294374 ecr 2423637829], length 0

Updates AdguardTeam#4128. Squashed commit of the following: commit c177750 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Thu Jan 20 17:01:02 2022 +0300 all: upd dnsproxy

b255ea006 · 2023-06-18T09:46:47Z

Hi,

i do have a similar issue, i do guess.
What does the following mean? And how do i fix it?

Jun 18 10:11:11 AdGuardHome[6467]: 2023/06/18 10:11:11.578252 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:52847: read: connection reset by peer
Jun 18 10:11:12 AdGuardHome[6467]: 2023/06/18 10:11:12.494192 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:52854: read: connection reset by peer
Jun 18 10:11:12 AdGuardHome[6467]: 2023/06/18 10:11:12.801723 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:52857: read: connection reset by peer
Jun 18 10:11:59 AdGuardHome[6467]: 2023/06/18 10:11:59.411092 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:52925: read: connection reset by peer
Jun 18 10:16:07 AdGuardHome[6467]: 2023/06/18 10:16:07.238143 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53212: read: connection reset by peer
Jun 18 10:16:07 AdGuardHome[6467]: 2023/06/18 10:16:07.238428 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53210: read: connection reset by peer
Jun 18 10:16:59 AdGuardHome[6467]: 2023/06/18 10:16:59.232312 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53272: read: connection reset by peer
Jun 18 10:18:31 AdGuardHome[6467]: 2023/06/18 10:18:31.099550 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53369: read: connection reset by peer
Jun 18 10:21:58 AdGuardHome[6467]: 2023/06/18 10:21:58.526102 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53591: read: connection reset by peer
Jun 18 10:26:59 AdGuardHome[6467]: 2023/06/18 10:26:59.289523 [error] handling tcp: reading msg: reading len: read tcp 192.168.50.1:53->192.168.50.245:53902: read: connection reset by peer

AzagraMac · 2023-07-05T06:04:55Z

v0.107.33
2023/07/05 07:21:10.006437 [error] handling tcp: reading msg: reading len: tls: first record does not look like a TLS handshake

Freebase394 · 2023-07-15T00:17:26Z

Hi everyone ?

My VERSION: 15/07/2023(dd/mm/yyyy) --> "Version: v0.108.0-b.41"
NOTE: In my case DoT is fully working (for the client) too!

But its normal to print this if i have ? :

log:
file: /opt/AdGuardHome/log_adguard.log
max_backups: 10
max_size: 200
max_age: 60
compress: true
local_time: true
verbose: true

RESULT:
...
2023/07/15 01:09:46.528247 19771#120 [debug] https://doh.familyshield.opendns.com:443/dns-query: sending request over tcp: A rr2---sn-apn7en7e.googlevideo.com.
2023/07/15 01:09:46.531616 19771#116 [debug] handling tcp: reading msg: connection is closed; original error: reading len: EOF
2023/07/15 01:09:46.635003 19771#117 [debug] https://doh.familyshield.opendns.com:443/dns-query: response received over tcp: ok
2023/07/15 01:09:46.635069 19771#117 [debug] time.Duration.Milliseconds(): upstream https://doh.familyshield.opendns.com:443/dns-query successfully finished exchange of ;rr2---sn-apn7en7e.googlevideo.com. IN HTTPS. Elapsed 108.237113ms.
2023/07/15 01:09:46.635094 19771#117 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).replyFromUpstream(): RTT: 108.280804ms
2023/07/15 01:09:46.635119 19771#117 [debug] dnsproxy: cache: ttl calculated to be 0; not caching
2023/07/15 01:09:46.635139 19771#117 [debug] dnsforward: finished processing upstream
2023/07/15 01:09:46.635155 19771#117 [debug] dnsforward: started processing filtering after resp
2023/07/15 01:09:46.635173 19771#117 [debug] dnsforward: finished processing filtering after resp
2023/07/15 01:09:46.635188 19771#117 [debug] dnsforward: ipset: started processing
2023/07/15 01:09:46.635205 19771#117 [debug] dnsforward: ipset: finished processing
2023/07/15 01:09:46.635221 19771#117 [debug] dnsforward: started processing querylog and stats
2023/07/15 01:09:46.635240 19771#117 [debug] dnsforward: client ip for stats and querylog: 192.168.50.72
2023/07/15 01:09:46.635277 19771#117 [debug] dnsforward: finished processing querylog and stats
2023/07/15 01:09:46.635304 19771#117 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 32680
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;rr2---sn-apn7en7e.googlevideo.com. IN HTTPS

2023/07/15 01:09:46.635361 19771#117 [debug] handling tcp: reading msg: connection is closed; original error: reading len: EOF
...

ainar-g added the enhancement label Jan 19, 2022

sinclairpaul mentioned this issue Jan 20, 2022

Permanent TCP i/o timeout error messages in log hassio-addons/addon-adguard-home#295

Closed

ainar-g added the P4: Low label Jan 20, 2022

ainar-g self-assigned this Jan 20, 2022

ainar-g added this to the v0.107.3 milestone Jan 20, 2022

adguard pushed a commit that referenced this issue Jan 20, 2022

Pull request: all: upd dnsproxy

1387197

Updates #4128. Squashed commit of the following: commit c177750 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Thu Jan 20 17:01:02 2022 +0300 all: upd dnsproxy

ainar-g closed this as completed Jan 21, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

AdGuardHome 0.107.2 error in handling tcp: reading msg: reading len: read tcp: i/o timeout #4128

AdGuardHome 0.107.2 error in handling tcp: reading msg: reading len: read tcp: i/o timeout #4128

grzesiczek1 commented Jan 12, 2022 •

edited

seanob86 commented Jan 12, 2022 •

edited

sturmstar commented Jan 13, 2022

grzesiczek1 commented Jan 13, 2022

ainar-g commented Jan 19, 2022

sturmstar commented Jan 19, 2022

grzesiczek1 commented Jan 19, 2022

ainar-g commented Jan 20, 2022

sturmstar commented Jan 21, 2022

zbulb commented Feb 5, 2022 •

edited

ainar-g commented Feb 9, 2022

dnomd343 commented Oct 4, 2022

ameshkov commented Oct 4, 2022

dnomd343 commented Oct 4, 2022 •

edited

ameshkov commented Oct 4, 2022

dnomd343 commented Oct 9, 2022

dnomd343 commented Oct 9, 2022

b255ea006 commented Jun 18, 2023

AzagraMac commented Jul 5, 2023

Freebase394 commented Jul 15, 2023 •

edited

AdGuardHome 0.107.2 error in handling tcp: reading msg: reading len: read tcp: i/o timeout #4128

AdGuardHome 0.107.2 error in handling tcp: reading msg: reading len: read tcp: i/o timeout #4128

Comments

grzesiczek1 commented Jan 12, 2022 • edited

Issue Details

Expected Behavior

Actual Behavior

Screenshots

Additional Information

seanob86 commented Jan 12, 2022 • edited

sturmstar commented Jan 13, 2022

grzesiczek1 commented Jan 13, 2022

ainar-g commented Jan 19, 2022

sturmstar commented Jan 19, 2022

grzesiczek1 commented Jan 19, 2022

ainar-g commented Jan 20, 2022

sturmstar commented Jan 21, 2022

zbulb commented Feb 5, 2022 • edited

ainar-g commented Feb 9, 2022

dnomd343 commented Oct 4, 2022

ameshkov commented Oct 4, 2022

dnomd343 commented Oct 4, 2022 • edited

ameshkov commented Oct 4, 2022

dnomd343 commented Oct 9, 2022

dnomd343 commented Oct 9, 2022

b255ea006 commented Jun 18, 2023

AzagraMac commented Jul 5, 2023

Freebase394 commented Jul 15, 2023 • edited

grzesiczek1 commented Jan 12, 2022 •

edited

seanob86 commented Jan 12, 2022 •

edited

zbulb commented Feb 5, 2022 •

edited

dnomd343 commented Oct 4, 2022 •

edited

Freebase394 commented Jul 15, 2023 •

edited