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.

Sign up for GitHub

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

Jump to bottom

Unnecessary normalizaiton and "hostname exists" error when renewing existing DHCP leases #3056

Closed
3 tasks done
alexpovel opened this issue May 2, 2021 · 14 comments
Closed
3 tasks done

Unnecessary normalizaiton and "hostname exists" error when renewing existing DHCP leases #3056

alexpovel opened this issue May 2, 2021 · 14 comments
Assignees
@ainar-g
Labels
bug P3: Medium
Milestone
v0.106.2

Comments

@alexpovel
Copy link

Have a question or an idea? Please search it on our forum to make sure it was not yet asked. If you cannot find what you had in mind, please submit it here.

Prerequisites

Please answer the following questions for yourself before submitting an issue. YOU MAY DELETE THE PREREQUISITES SECTION.

  • I am running the latest version
  • I checked the documentation and found no answer
  • I checked to make sure that this issue has not already been filed

Issue Details

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

Expected Behavior

DHCP leases working correctly.

Actual Behavior

DHCP leases are not working correctly. It's similar to #3053 . Updating from v0.105 to v0.106, DHCP leases were not working at all. I solved this pruning the entire working directory at /opt/adguardhome/work. It contains a leases.db JSON file with leases; maybe deleting just that would've been enough, but the nuclear option was simpler (which also deletes the stats, query log and more).

After nuking the leases, new clients were able to come in and get proper DHCP leases, and AGH would resolve their hostnames fine, like pecan in this example:

image

However, if clients try to get a lease again, it errors out with validating hostname: hostname exists and the original, correct hostname gets normalized to its hyphenated IP address, like the second client in the above screenshot. The corresponding log entry looks like:

[dhcpv4] 2021/05/02 12:51:40 Handling request from 0.0.0.0:68
2021/05/02 12:51:40 1#37878 [debug] dhcpv4: received message: DHCPv4 Message
  opcode: BootRequest
  hwtype: Ethernet
  hopcount: 0
  transaction ID: 0xa1e78acb
  num seconds: 0
  flags: Unicast (0x00)
  client IP: 0.0.0.0
  your IP: 0.0.0.0
  server IP: 0.0.0.0
  gateway IP: 0.0.0.0
  client MAC: 4d:23:c3:92:35:3b
  server hostname:
  bootfile name:
  options:
    Host Name: some-machine
    Requested IP Address: 192.168.137.61
    IP Addresses Lease Time: 2160h0m0s
    DHCP Message Type: REQUEST
    Parameter Request List: Subnet Mask, Router, Domain Name Server, Domain Name, NetBIOS over TCP/IP Name Server, NetBIOS over TCP/IP Node Type, LDAP, DNS Domain Search List, Classless Static Route, unknown (252)
    Maximum DHCP Message Size: 1500
    Client identifier: [1 77 50 113 127 35 33]

2021/05/02 12:51:40 1#37878 [info] dhcpv4: normalized hostname "some-machine" into "192-168-137-61"
2021/05/02 12:51:40 1#37878 [info] dhcpv4: warning: client hostname "some-machine" is invalid: validating hostname: hostname exists

I mean, I guess AGH is technically correct: the hostname exists. But the requesting machine is that same machine, so it should just overwrite that entry, no?

It seems that after a while (after all DHCP leases needed to have been renewed, 24h in my case), all hosts will eventually get "normalized" to their respective hyphenated IP addresses. They become unreachable under their ordinary hostname.
@Black8all
Copy link

Black8all commented May 2, 2021 •
edited
Loading

I have a quite similar issue #3053.

Here is a screenshot of my leases :

image

And a quick sample of my log :

2021/05/02 15:52:17 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:17 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:17 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:17 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:18 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:18 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:18 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:18 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:18 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:18 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:19 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:19 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:19 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:20 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:20 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:20 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:20 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:20 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:20 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:21 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:21 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:21 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:21 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:21 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:22 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:22 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:22 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:22 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:23 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:23 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:23 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:25 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:25 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:25 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:26 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:26 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:26 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:27 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:27 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:27 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:27 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:27 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:27 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:28 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:28 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:28 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:28 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:28 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:29 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:29 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:29 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:29 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:30 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:30 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:30 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:30 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:30 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:30 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:31 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:31 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:31 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:32 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:32 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:32 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:32 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:32 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:32 [info] dhcp: stored 30 leases in DB
2021/05/02 15:52:33 [info] dhcpv4: normalized hostname "ESP_839FAC" into "192-168-1-6"
2021/05/02 15:52:33 [info] dhcpv4: warning: client hostname "ESP_839FAC" is invalid: validating hostname: hostname exists
2021/05/02 15:52:33 [info] dhcp: stored 30 leases in DB

@alexpovel
Copy link
Author

@Black8all Exactly. Over night, my DHCP leases list has now turned into something akin to your screenshot. Only a long list of hyphenated IPv4s, no proper hostnames anymore. This breaks large parts of the entire home network.

@zadigre
Copy link

zadigre commented May 3, 2021

I had a similar problem with 0.106.1...
I installed edge channel build... and it seems fixed... most of my hostnames have returned to the correct hostname after 24 hours.

@ainar-g ainar-g added this to the v0.106.2 milestone May 4, 2021
@ainar-g
Copy link
Contributor

ainar-g commented May 4, 2021

Hello and thank you for the thorough report. We can reproduce the issue and will try to fix it in the next couple of days.

@ainar-g ainar-g changed the title DHCP skips and "normalizes" existing hostnames instead of renewing Unnecessary normalizaiton and "hostname exists" error when renewing existing DHCP leases May 4, 2021
@ainar-g ainar-g mentioned this issue May 4, 2021
Closed
@zadigre
Copy link

zadigre commented May 5, 2021 •
edited
Loading

I thought it was fixed in the latest edge channel build... but it's not... I'm getting a bunch of "normalized" host name (14 now out of my 22 devices that do not get a static IP address)
and also since this problem began happening, some device that rejoin the network after some time are slow to get their IP address... like my iPhone take a few seconds/minutes to get it instead of just getting is instantly.

adguard pushed a commit that referenced this issue May 6, 2021
@ainar-g
Pull request: dhcpd: imp normalization, validation
f717776 
Updates #3056.

Squashed commit of the following:

commit 875954f
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 19:54:24 2021 +0300

    all: imp err msgs

commit c6ea471
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 17:55:12 2021 +0300

    dhcpd: imp normalization, validation
@ainar-g
Copy link
Contributor

ainar-g commented May 6, 2021

@alexpovel, @zadigre, we've pushed a possible fix to the edge channel. Can you please check that DHCP works better now?

adguard pushed a commit that referenced this issue May 6, 2021
@ainar-g
cherry-pick: dhcpd: imp normalization, validation
66d47b1 
Updates #3056.

Squashed commit of the following:

commit 875954f
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 19:54:24 2021 +0300

    all: imp err msgs

commit c6ea471
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 17:55:12 2021 +0300

    dhcpd: imp normalization, validation
@zadigre
Copy link

zadigre commented May 6, 2021

I won't be able to test the dhcp server now...
I had to stop using it because some devices were slow to get their IP address... and sometimes they weren't able to get it at all for some reason. It even caused me trouble adding some new devices to my homekit setup yesterday night.
I disabled dhcp in adguard home, reenabled it in my router... and all is fine. I leave it that way for now.
Hopefully @alexpovel can test it... and if all is fine, I might use it again in the near future.

@alexpovel
Copy link
Author

I have removed /etc/adguardhome/work/leases.db (although they still show in the dashboard), upgraded to adguard/adguardhome:edge (v0.106.0-a.57+4c6bf68d) and decreased lease durations to 3600s. I will report back tomorrow with how it went. Thanks so far!

@ainar-g ainar-g self-assigned this May 6, 2021
@alexpovel
Copy link
Author

alexpovel commented May 7, 2021 •
edited
Loading

Okay, some results are in.

The list of DHCP hostnames that got a lease from AGH now indeed looks fine, no more hyphenated IP addresses. There's new problems.

  1. Now there's empty entries:

    image

    I cannot trace the corresponding MAC addresses, they don't seem to belong to any physical device here.

  2. Everything works less than before because local_domain_name does not work anymore. No host under that FQDN is reachable. For example, a host some-machine under the local_domain_name my.local.domain.com will simply be forwarded to upstream DNS servers. The corresponding log entry is:

    2222536-2021-05-07T07:33:03.747971630Z 2021/05/07 07:33:03 1#528627 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): Start handling new UDP packet from 192.168.0.112:55915
2222537-2021-05-07T07:33:03.748294034Z 2021/05/07 07:33:03 1#528627 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 47428
2222538-2021-05-07T07:33:03.748370793Z ;; flags: rd ad; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
2222539-2021-05-07T07:33:03.748487458Z
2222540-2021-05-07T07:33:03.748544958Z ;; QUESTION SECTION:
2222541:2021-05-07T07:33:03.748598994Z ;some-machine.my.local.domain.com.      IN       A
2222542-2021-05-07T07:33:03.748653679Z
2222543-2021-05-07T07:33:03.748704586Z ;; ADDITIONAL SECTION:
2222544-2021-05-07T07:33:03.748757085Z
2222545-2021-05-07T07:33:03.748807714Z ;; OPT PSEUDOSECTION:
2222546-2021-05-07T07:33:03.748859640Z ; EDNS: version 0; flags: ; udp: 4096
2222547-2021-05-07T07:33:03.748911898Z ; COOKIE: 7ee227305ee82edf
2222548-2021-05-07T07:33:03.748964435Z
2222549:2021-05-07T07:33:03.749385653Z 2021/05/07 07:33:03 1#528627 [debug] AutoHosts: answer: some-machine.my.local.domain.com -> []
2222550:2021-05-07T07:33:03.751261430Z 2021/05/07 07:33:03 1#528629 [debug] https://dns.quad9.net:443/dns-query: sending request A some-machine.my.local.domain.com.
2222551:2021-05-07T07:33:03.751380522Z 2021/05/07 07:33:03 1#528628 [debug] https://dns.digitale-gesellschaft.ch:443/dns-query: sending request A some-machine.my.local.domain.com.
2222552:2021-05-07T07:33:03.751767110Z 2021/05/07 07:33:03 1#528630 [debug] https://doh.opendns.com:443/dns-query: sending request A some-machine.my.local.domain.com.
2222553-2021-05-07T07:33:03.770710438Z 2021/05/07 07:33:03 1#528629 [debug] https://dns.quad9.net:443/dns-query: response: ok
2222554-2021-05-07T07:33:03.788911866Z 2021/05/07 07:33:03 1#528630 [debug] https://doh.opendns.com:443/dns-query: response: ok
2222555-2021-05-07T07:33:03.821133209Z 2021/05/07 07:33:03 1#528628 [debug] https://dns.digitale-gesellschaft.ch:443/dns-query: response: ok
2222556:2021-05-07T07:33:03.821547556Z 2021/05/07 07:33:03 1#528627 [debug] some-machine.my.local.domain.com.: no fastest IP found, using the first response
2222557-2021-05-07T07:33:03.821614426Z 2021/05/07 07:33:03 1#528627 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).Resolve(): RTT: 71 ms
2222558:2021-05-07T07:33:03.821957497Z 2021/05/07 07:33:03 1#528627 [debug] github.com/AdguardTeam/dnsproxy/proxy.isCacheable(): some-machine.my.local.domain.com.: refusing to cache a NOERROR response with no answers
2222559-2021-05-07T07:33:03.822285993Z 2021/05/07 07:33:03 1#528627 [debug] ipset: starting processing
2222560-2021-05-07T07:33:03.822644101Z 2021/05/07 07:33:03 1#528627 [debug] ipset: skipped processing for request
2222561-2021-05-07T07:33:03.823067578Z 2021/05/07 07:33:03 1#528627 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 47428
2222562-2021-05-07T07:33:03.823141466Z ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
2222563-2021-05-07T07:33:03.823194706Z
2222564-2021-05-07T07:33:03.823246317Z ;; QUESTION SECTION:
2222565:2021-05-07T07:33:03.823297594Z ;some-machine.my.local.domain.com.      IN       A
2222566-2021-05-07T07:33:03.823350575Z
2222567-2021-05-07T07:33:03.823401130Z ;; AUTHORITY SECTION:
2222568-2021-05-07T07:33:03.823452796Z domain.com.    3600    IN      SOA     dns1.registrar-servers.com. hostmaster.registrar-servers.com. 1620354464 43200 3600 604800 3601
2222569-2021-05-07T07:33:03.823562351Z
2222570-2021-05-07T07:33:03.823615573Z ;; ADDITIONAL SECTION:
2222571-2021-05-07T07:33:03.823666646Z
2222572-2021-05-07T07:33:03.823716720Z ;; OPT PSEUDOSECTION:
2222573-2021-05-07T07:33:03.823767719Z ; EDNS: version 0; flags: do; udp: 4096
2222574-2021-05-07T07:33:03.823818515Z

    Adding [/my.local.domain.com/]192.168.137.10 to the DNS settings, where 192.168.137.10 is the AGH DNS/DHCP server IP, will cause requests to time out after 10s with a SERVFAIL. For each request, there are a couple groups of lines like this:

    2021/05/07 08:01:41 1#558440 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): error handling DNS (udp) request: talking to dnsUpstream failed, cause: read udp 192.168.137.10:46380->192.168.137.10:53: i/o timeout
2021/05/07 08:01:41 1#558441 [debug] 192.168.137.10:53: response: read udp 192.168.137.10:46711->192.168.137.10:53: i/o timeout
2021/05/07 08:01:41 1#558441 [debug] github.com/AdguardTeam/dnsproxy/upstream.exchange(): upstream 192.168.137.10:53 failed to exchange ;some-machine.my.local.domain.com.  IN       A in 10003 milliseconds. Cause: read udp 192.168.137.10:46711->192.168.137.10:53: i/o timeout
2021/05/07 08:01:41 1#558441 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).Resolve(): RTT: 10004 ms
2021/05/07 08:01:41 1#558441 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: SERVFAIL, id: 56321
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;some-machine.my.local.domain.com.       IN       A

EDIT:

I relaunched the Docker stack and removed the edge tag. I'm now on v0.106.2. After reboot, the empty entries above were normalized:

image

But maybe that's intended behaviour and those are junk entires to be flushed out soon.

The good news is that local domain resolution works again in that version.

@ameshkov
Copy link
Member

ameshkov commented May 7, 2021

What about local_domain_name on v0.106.2? Is it still not working?

@alexpovel
Copy link
Author

It works there!

@ainar-g
Copy link
Contributor

ainar-g commented May 11, 2021

Just to be clear, are there any more issues here that aren't fixed in v0.106.2?

@Black8all
Copy link

I don't know if it's always the same error as #3053?

@alexpovel
Copy link
Author

@ainar-g , thanks for asking. I've had v0.106.2 running fine for those 4 days now. As far as I'm concerned, this issue can be closed.

heyxkhoa pushed a commit to heyxkhoa/AdGuardHome that referenced this issue Mar 20, 2023
@ainar-g @heyxkhoa
Pull request: dhcpd: imp normalization, validation
627088b 
Updates AdguardTeam#3056.

Squashed commit of the following:

commit 875954f
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 19:54:24 2021 +0300

    all: imp err msgs

commit c6ea471
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed May 5 17:55:12 2021 +0300

    dhcpd: imp normalization, validation
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ainar-g ainar-g

Labels
bug P3: Medium
Projects
None yet
Milestone
v0.106.2
Development

No branches or pull requests
5 participants
@zadigre @ainar-g @ameshkov @alexpovel @Black8all