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

Missing log entries #3772

Closed
timkgh opened this issue Oct 27, 2021 · 8 comments
Closed

Missing log entries #3772

timkgh opened this issue Oct 27, 2021 · 8 comments
Assignees
@IldarKamalov @EugeneOne1
Labels
bug P3: Medium
Milestone
v0.107.0

Comments

@timkgh
Copy link

timkgh commented Oct 27, 2021 •
edited

v0.107.0-b.13

Not sure whether this has to do with optimistic caching or using domain specific upstreams or a combination of both. I use optimistic caching and the rule below for upstreams because I don't want safe search from the general upstreams:
[/www.google.com/www.youtube.com/m.youtube.com/youtubei.googleapis.com/youtube.googleapis.com/www.youtube-nocookie.com/]https://8.8.8.8/dns-query

Initially I see a few entries in the query.json* log files for the google/youtube domains above with an Upstream of 8.8.8.8 as expected but then I never see any more entries again with an Upstream set for these domains. There are log entries without Upstream and a very short Elapsed time which I assume are served from the cache.

I'm not sure why, whether AGH always answers from the cache or the log file is just missing entries when the query is the result of an optimistic cache miss.
@ainar-g
Copy link
Contributor

ainar-g commented Oct 27, 2021

It's most probably cache. The easiest way to confirm that is to either decrease the cache size or to disable it by setting the size to zero and look if the records appear. Remember, though, that clients also cache records, so it may take a while.

@ainar-g ainar-g added the waiting for data Waiting for users to provide more data. label Oct 27, 2021
@timkgh
Copy link
Author

timkgh commented Oct 27, 2021

@ainar-g I can confirm it is the optimistic cache setting, if I turn it off the entries start showing up in the log.

I'd consider this a bug, even if the upstream queries happen in the background, they should still be logged.

@ainar-g
Copy link
Contributor

ainar-g commented Oct 27, 2021

That sounds reasonable.

@ameshkov, please confirm. Sounds like a bug in the current optimistic caching implementation.

@ainar-g ainar-g added bug P3: Medium and removed waiting for data Waiting for users to provide more data. labels Oct 27, 2021
@ainar-g ainar-g added this to the v0.107.0 milestone Oct 27, 2021
@ainar-g ainar-g self-assigned this Oct 27, 2021
@ameshkov
Copy link
Member

@ainar-g yep, those queries should be reported to the log

@ainar-g ainar-g removed their assignment Nov 18, 2021
@ameshkov
Copy link
Member

@ainar-g @EugeneOne1 I suggest solving it in the following way: add "Upstream" information to the cache items. Also, add a marker that distinguishes cached items from those resolved from the upstream.

Here's how these records should look like in the Query Log's response details:
image

@ainar-g ainar-g mentioned this issue Nov 24, 2021
Closed
adguard pushed a commit to AdguardTeam/dnsproxy that referenced this issue Nov 25, 2021
@EugeneOne1
Pull request: 3772 cache upstreams
c51ae88 
Merge in DNS/dnsproxy from 3772-cache-upstreams to master

Updates AdguardTeam/AdGuardHome#3772.

Squashed commit of the following:

commit beed5d5
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 13:46:36 2021 +0300

    proxy: fix reading uint

commit dff7d75
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 13:44:32 2021 +0300

    proxy: imp docs

commit c96cc94
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 13:27:35 2021 +0300

    proxy: rm unsafe

commit d36871a
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Wed Nov 24 21:28:21 2021 +0300

    proxy: imp code quality

commit 25f966c
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Wed Nov 24 21:06:22 2021 +0300

    proxy: imp cache tests

commit c0202b6
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Wed Nov 24 18:21:11 2021 +0300

    proxy: cache upstreams
adguard pushed a commit that referenced this issue Dec 7, 2021
@EugeneOne1
Pull request: 3772 cache upstreams
434032f 
Merge in DNS/adguard-home from 3772-cache-upstreams to master

Updates #3772.

Squashed commit of the following:

commit 809e874
Merge: 5774798 2d328ea
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Tue Dec 7 17:15:59 2021 +0300

    Merge branch 'master' into 3772-cache-upstreams

commit 5774798
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:48:38 2021 +0300

    client: fix formatting

commit 4b4bb66
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:47:18 2021 +0300

    client: remove comment

commit a2a9f90
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:45:31 2021 +0300

    client: handle cached upstream

commit a56804c
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:33:43 2021 +0300

    querylog: rm todo

commit 16c0a62
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:31:53 2021 +0300

    all: revise log of changes

commit 9f4b793
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:23:42 2021 +0300

    WIP

commit 7fbc6d5
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:03:42 2021 +0300

    all: imp upstream info in querylog
@EugeneOne1
Copy link
Member

EugeneOne1 commented Dec 7, 2021 •
edited

@timkgh, hello again. It should be finally fixed in the latest build from the edge channel. Could you please install it and check if upstream servers of cached answers are now displayed and labeled?

@EugeneOne1
Copy link
Member

@timkgh, I'll close the issue for now. Please feel free to reopen it if the introduced logic will produce any problems.

@timkgh
Copy link
Author

timkgh commented Dec 15, 2021

I will give it a try in b16 and report back if there are still issues.

heyxkhoa pushed a commit to heyxkhoa/AdGuardHome that referenced this issue Mar 20, 2023
@EugeneOne1 @heyxkhoa
Pull request: 3772 cache upstreams
72a8839 
Merge in DNS/adguard-home from 3772-cache-upstreams to master

Updates AdguardTeam#3772.

Squashed commit of the following:

commit 809e874
Merge: 5774798 2d328ea
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Tue Dec 7 17:15:59 2021 +0300

    Merge branch 'master' into 3772-cache-upstreams

commit 5774798
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:48:38 2021 +0300

    client: fix formatting

commit 4b4bb66
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:47:18 2021 +0300

    client: remove comment

commit a2a9f90
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:45:31 2021 +0300

    client: handle cached upstream

commit a56804c
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:33:43 2021 +0300

    querylog: rm todo

commit 16c0a62
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:31:53 2021 +0300

    all: revise log of changes

commit 9f4b793
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:23:42 2021 +0300

    WIP

commit 7fbc6d5
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:03:42 2021 +0300

    all: imp upstream info in querylog
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@IldarKamalov IldarKamalov

@EugeneOne1 EugeneOne1

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

No branches or pull requests
5 participants
@IldarKamalov @ainar-g @ameshkov @timkgh @EugeneOne1