Incorrect ClientID in query log interface when using client id from DoH query string

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, ARM64

Installation

GitHub releases or script from README

Setup

On one machine

AdGuard Home version

v0.107.53

Action

I want to use client id in DoH query string (/dns-query/client-id) but query log most of the time shows "new" client with PTR for cellular ip instead of configured persistent client. But there is also some requests which have correct client id.

Expected result

Query log should always show saved client id

Actual result

Most of the time query log don't show client id:

but for some requests it works correctly:

Additional information and/or screenshots

andrey@rpi5 ~> lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 12 (bookworm)
Release:    12
Codename:   bookworm
andrey@rpi5 ~> sudo /opt/AdGuardHome/AdGuardHome --version
AdGuard Home, version v0.107.53

there is configured persistent client iphone-andrey:

clients:
  runtime_sources:
    whois: true
    arp: true
    rdns: true
    dhcp: true
    hosts: true
...
      name: iphone-andrey
      ids:
        - 192.168.1.25
        - 192.168.2.148
      tags: []
      use_global_settings: true
      ignore_querylog: false
...

doh.mobileconfig iOS profile server url contains client id:

...
                <key>DNSSettings</key>
                <dict>
                    <key>DNSProtocol</key>
                    <string>HTTPS</string>
                    <key>ServerAddresses</key>
                    <array>
                      <string>123.123.123.123</string>
                     </array>
                    <key>ServerURL</key>
                    <string>https://dns.example.com/dns-query/iphone-andrey</string>
                </dict>
...

As I see from Adguard log it captures client id but failed? to map it to persistent clients:

 no clients with ip 111.111.111.111 and clientid "iphone-andrey"

Here 111.111.111.111 is cellular provider address. In query log I see all requests to /dns-query/iphone-andrey as "new" clients with PTR name, not my saved client name.

however in querylog.json I see correct client id:

{"T":"2024-11-04T14:43:49.583843078+03:00","QH":"www.macrumors.com","QT":"A","QC":"IN","CID":"iphone-andrey","CP":"doh","Upstream":"https://dns.nextdns.io:443/example","Answer":"AACBgAABAAMAAAABA3d3dwltYWNydW1vcnMDY29tAAABAAHADAABAAEAAAEsAARoFgNqwAwAAQABAAABLAAEaBYCasAMAAEAAQAAASwABKxDFoIAACkCAAAAAAAAAA==","IP":"111.111.111.111","Result":{},"Elapsed":61826071}
{"T":"2024-11-04T14:43:49.585455478+03:00","QH":"www.macrumors.com","QT":"HTTPS","QC":"IN","CID":"iphone-andrey","CP":"doh","Upstream":"https://dns.nextdns.io:443/example","Answer":"AACBgAABAAEAAAABA3d3dwltYWNydW1vcnMDY29tAABBAAHADABBAAEAAAEsAB0AAQAAAQAGAmgzAmgyAAQADGgWAmpoFgNqrEMWggAAKQIAAAAAAAAA","IP":"111.111.111.111","Result":{},"Elapsed":64415366}
{"T":"2024-11-04T14:43:49.746700247+03:00","QH":"images.macrumors.com","QT":"A","QC":"IN","CID":"iphone-andrey","CP":"doh","Upstream":"https://dns.nextdns.io:443/example","Answer":"AACBgAABAAMAAAABBmltYWdlcwltYWNydW1vcnMDY29tAAABAAHADAABAAEAAADzAARoFgJqwAwAAQABAAAA8wAErEMWgsAMAAEAAQAAAPMABGgWA2oAACkCAAAAAAAAAA==","IP":"111.111.111.111","Result":{},"Elapsed":58154694}
{"T":"2024-11-04T14:43:49.74787207+03:00","QH":"images.macrumors.com","QT":"HTTPS","QC":"IN","CID":"iphone-andrey","CP":"doh","Upstream":"https://dns.nextdns.io:443/example","Answer":"AACBgAABAAEAAAABBmltYWdlcwltYWNydW1vcnMDY29tAABBAAHADABBAAEAAADzAB0AAQAAAQAGAmgzAmgyAAQADGgWAmpoFgNqrEMWggAAKQIAAAAAAAAA","IP":"111.111.111.111","Result":{},"Elapsed":58279528}

log for request:

2024/11/04 14:43:49.687270 3295#2813 [debug] dnsproxy: incoming https request url="/dns-query/iphone-andrey?dns=AAABAAABAAAAAAABBmltYWdlcwltYWNydW1vcnMDY29tAAABAAEAACkCAAAAAAAATwAPAAIAAAAMAEUAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"
2024/11/04 14:43:49.687338 3295#2791 [debug] dnsproxy: using ip address from http request addr=111.111.111.111
2024/11/04 14:43:49.687369 3295#2813 [debug] dnsproxy: using ip address from http request addr=111.111.111.111
2024/11/04 14:43:49.687402 3295#2791 [debug] dnsproxy: request came from proxy server addr=127.0.0.1:48990
2024/11/04 14:43:49.687468 3295#2813 [debug] dnsproxy: request came from proxy server addr=[::1]:40450
2024/11/04 14:43:49.687577 3295#2813 [debug] dnsproxy: in line_num=1 line=";; opcode: QUERY, status: NOERROR, id: 0"
2024/11/04 14:43:49.687625 3295#2791 [debug] dnsproxy: in line_num=1 line=";; opcode: QUERY, status: NOERROR, id: 0"
2024/11/04 14:43:49.687682 3295#2813 [debug] dnsproxy: in line_num=2 line=";; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1"
2024/11/04 14:43:49.687751 3295#2813 [debug] dnsproxy: in line_num=3 line=""
2024/11/04 14:43:49.687825 3295#2813 [debug] dnsproxy: in line_num=4 line=";; OPT PSEUDOSECTION:"
2024/11/04 14:43:49.687763 3295#2791 [debug] dnsproxy: in line_num=2 line=";; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1"
2024/11/04 14:43:49.687925 3295#2813 [debug] dnsproxy: in line_num=5 line="; EDNS: version 0; flags:; udp: 512"
2024/11/04 14:43:49.688011 3295#2813 [debug] dnsproxy: in line_num=6 line="; EDE: 0 (Other): ()"
2024/11/04 14:43:49.688061 3295#2791 [debug] dnsproxy: in line_num=3 line=""
2024/11/04 14:43:49.688093 3295#2813 [debug] dnsproxy: in line_num=7 line="; PADDING: 000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000"
2024/11/04 14:43:49.688167 3295#2813 [debug] dnsproxy: in line_num=8 line=""
2024/11/04 14:43:49.688248 3295#2813 [debug] dnsproxy: in line_num=9 line=";; QUESTION SECTION:"
2024/11/04 14:43:49.688327 3295#2813 [debug] dnsproxy: in line_num=10 line=";images.macrumors.com.\tIN\t A"
2024/11/04 14:43:49.688337 3295#2791 [debug] dnsproxy: in line_num=4 line=";; OPT PSEUDOSECTION:"
2024/11/04 14:43:49.688401 3295#2813 [debug] dnsproxy: in line_num=11 line=""
2024/11/04 14:43:49.688464 3295#2791 [debug] dnsproxy: in line_num=5 line="; EDNS: version 0; flags:; udp: 512"
2024/11/04 14:43:49.688526 3295#2813 [debug] dnsforward: started processing initial
2024/11/04 14:43:49.688634 3295#2813 [debug] applying filters: looking for client with ip 111.111.111.111 and clientid "iphone-andrey"
2024/11/04 14:43:49.688704 3295#2813 [debug] applying filters: no clients with ip 111.111.111.111 and clientid "iphone-andrey"
2024/11/04 14:43:49.688764 3295#2813 [debug] dnsforward: finished processing initial
2024/11/04 14:43:49.688634 3295#2791 [debug] dnsproxy: in line_num=6 line="; EDE: 0 (Other): ()"
2024/11/04 14:43:49.688812 3295#2813 [debug] dnsforward: started processing ddr
2024/11/04 14:43:49.688647 3295#44 [debug] clients: processing 111.111.111.111 with rdns
2024/11/04 14:43:49.688884 3295#2813 [debug] dnsforward: finished processing ddr
2024/11/04 14:43:49.688899 3295#44 [debug] clients: finished processing 111.111.111.111 with rdns in 259.724µs
2024/11/04 14:43:49.688919 3295#44 [debug] clients: processing 111.111.111.111 with whois
2024/11/04 14:43:49.688943 3295#44 [debug] clients: finished processing 111.111.111.111 with whois in 22.111µs
2024/11/04 14:43:49.688997 3295#2813 [debug] dnsforward: started processing dhcp hosts
2024/11/04 14:43:49.689009 3295#2791 [debug] dnsproxy: in line_num=7 line="; PADDING: 000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000"
2024/11/04 14:43:49.689062 3295#2813 [debug] dnsforward: finished processing dhcp hosts
2024/11/04 14:43:49.689114 3295#2813 [debug] dnsforward: started processing dhcp addrs
2024/11/04 14:43:49.689133 3295#2791 [debug] dnsproxy: in line_num=8 line=""
2024/11/04 14:43:49.689179 3295#2813 [debug] dnsforward: finished processing dhcp addrs
2024/11/04 14:43:49.689239 3295#2813 [debug] dnsforward: started processing filtering before req
2024/11/04 14:43:49.689262 3295#2791 [debug] dnsproxy: in line_num=9 line=";; QUESTION SECTION:"
2024/11/04 14:43:49.689381 3295#2813 [debug] dnsforward: finished processing filtering before req
2024/11/04 14:43:49.689423 3295#2813 [debug] dnsforward: started processing upstream
2024/11/04 14:43:49.689450 3295#2791 [debug] dnsproxy: in line_num=10 line=";images.macrumors.com.\tIN\t HTTPS"
2024/11/04 14:43:49.689511 3295#2791 [debug] dnsproxy: in line_num=11 line=""
2024/11/04 14:43:49.689574 3295#2791 [debug] dnsforward: started processing initial
2024/11/04 14:43:49.689651 3295#2791 [debug] applying filters: looking for client with ip 111.111.111.111 and clientid "iphone-andrey"
2024/11/04 14:43:49.689753 3295#44 [debug] clients: processing 111.111.111.111 with rdns
2024/11/04 14:43:49.689775 3295#44 [debug] clients: finished processing 111.111.111.111 with rdns in 65.612µs
2024/11/04 14:43:49.689789 3295#2791 [debug] applying filters: no clients with ip 111.111.111.111 and clientid "iphone-andrey"
2024/11/04 14:43:49.689833 3295#2791 [debug] dnsforward: finished processing initial
2024/11/04 14:43:49.689792 3295#44 [debug] clients: processing 111.111.111.111 with whois
2024/11/04 14:43:49.689878 3295#44 [debug] clients: finished processing 111.111.111.111 with whois in 83.352µs
2024/11/04 14:43:49.689942 3295#2791 [debug] dnsforward: started processing ddr
2024/11/04 14:43:49.690020 3295#2791 [debug] dnsforward: finished processing ddr
2024/11/04 14:43:49.690077 3295#2791 [debug] dnsforward: started processing dhcp hosts
2024/11/04 14:43:49.690117 3295#2791 [debug] dnsforward: finished processing dhcp hosts
2024/11/04 14:43:49.690151 3295#2791 [debug] dnsforward: started processing dhcp addrs
2024/11/04 14:43:49.690186 3295#2791 [debug] dnsforward: finished processing dhcp addrs
2024/11/04 14:43:49.690220 3295#2791 [debug] dnsforward: started processing filtering before req
2024/11/04 14:43:49.690268 3295#2791 [debug] filtering: unsupported qtype 65
2024/11/04 14:43:49.690360 3295#2791 [debug] dnsforward: finished processing filtering before req
2024/11/04 14:43:49.690395 3295#2791 [debug] dnsforward: started processing upstream

AdguardTeam / AdGuardHome