The query log refreshes itself, goes back to the beginning and into the future !

[mgcWil]

Prerequisites

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

• I am running the latest version (0.104.0)
• 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:
  • 0.104.0
• How did you setup DNS configuration:
• If it's a router or IoT, please write device model:
• Operating system and version:
  • Behaviors observed on two different Windows 10 machines, Firefox 81.0.2

Expected Behavior

Actual Behavior

Hello!
I also notice strange behaviors of the query log which can go in an infinite loop without using the mouse wheel, refresh itself completely by itself and go back to the beginning, making any progress impossible !

I also notice inconsistencies in the chronology, sometimes the following lines indicate a more recent time !

My AGH is incrementing a TXT log, non verbose, I found many lines with "[error] Couldn't find timestamp:".
I finally noticed that this incrementing is done when consulting the query log with the scroll wheel, see the screenshots.

Screenshots

Screenshot:

"Back to the future !"

Real-time incrementing of the TXT journal with lines "[error] Couldn't find timestamp:"

Infinite loop without using the mouse wheel, the scrollbar or the keyboard !

Additional Information

I had noticed these problems with the beta 0.104.0-beta3, and found that the query log could not be exploitable, seeing that the navigation buttons had disappeared in the version 0.104.0, I thought that the bugs had been fixed...

For me, it's back to 0.103.0, whose query log has some problems too, but less catastrophic.

I wanted to bring my little contribution, especially in image and my feeling.

I do not doubt that a solution will be found, I hope quickly (but I will be patient) in the form of a patch on this version 0.104 ? Maybe, in the meantime ; good work to all and thank you ;)

[ameshkov]

My AGH is incrementing a TXT log, non verbose, I found many lines with "[error] Couldn't find timestamp:".

Please check the "edge" channel build, this issue has been fixed there.

[mgcWil]

version v0.104.0-SNAPSHOT-3cc5bf21 installed in another folder, started (without data folder), and tested :
1- The lines "[error] Couldn't find timestamp:" don't appear in the TXT log, OK,
2- but the inconsistencies in the chronology still exist :(

3- The query log has completely refreshed to go back to the beginning as soon as the end (or rather the beginning) of the records reached !
:(

[ainar-g]

Hi! The query log fix landed after that snapshot. Please try the newly released v0.104.1, it should fix that issue.

[mgcWil]

Well, v0.104.1 installed (update from v0.104.0), started (without data folder), and tested :
Positive points :
1- The lines "[error] Couldn't find timestamp:" really don't appear in the TXT log anymore, cool !
2- The query log did NOT refresh completely to go back to the beginning as soon as the end (or rather the beginning) of the records reached, cool again !

But, the negative point: The inconsistencies in the chronology still exist, not cool, arf :(

[ameshkov]

The query is written to the log when it has been processed (so they are ordered by "end time"). But the time you're seeing in the log is the time when the query processing has been started.

[mgcWil]

Okay, I didn't know that. It's hard to take in, but I get it.
So it's not a bug at all ?
To avoid misunderstandings, and improve readability, wouldn't it be simpler if the log shows us the "end time", just ?

[ameshkov]

Yeah, that's generally not a bug, but there are ways to mitigate this.

[mgcWil]

OK, so the query log shows us the time at which the processing of the request was launched (the demand), classifying these requests by order of processing (the response), did I understand correctly ?

By saying "there are ways to mitigate this" what do you mean ?
1- that response times can be improved ? On the AGH side, Upstream... (my self-esteem just took a hit there :) )
2- that the query log could display requests by processing order only (the response), or the reverse (but it might be less relevant, my moldy Upstreams have random response times) ? And here it concerns you, the coders, AH ! (My ego is already better there !)
3- one or other ways ?

What's up?
Take the time to answer me, there's no hurry, there's no bug (just my bad Upstreams and a strange query log...) !
;)

[ameshkov]

The queries are buffered in-memory before they're dumped into the query log file. We could keep them sorted at that point. There's still a probability that the query that's processed right after the buffer is dumped will get out of sort.

[mgcWil]

OK, I understand that here you are expressing that you could make an improvement ?

I will persist in the Bug !
I made a short extraction from the query log, keeping only the "Time" column, then numbered in chronological order each displayed line. Using a simple formula in a spreadsheet, I wanted to highlight the time differences.
The result is :

• that the time differences between two rows are more than a few seconds.
• that the log sometimes displays identical time ranges, loops, several times.

No screenshot this time, but two XLSX.
Copie_Query_Log.xlsx
Copie_Query_Log_local.xlsx

[ameshkov]

Maybe. We're planning to take a deeper look into it anyway so your input would be useful.

[mgcWil]

Great 👍
Here's another extraction, at a different time, the results are identical to the first one.
Copie_Query_Log_local_2.xlsx

I wanted to make another one from the query log of the first machine, but I couldn't do it !
AGH has been running since 19H yesterday, it hasn't restarted since, and the query log doesn't show me anything before 14:02:44 today on the "All queries" filtering. On the other hand, it goes further with the "Processed" filtering !
Damn animal !

Thank you !

[ainar-g]

We've added a small mitigation in snapshot 6e615c6. Unfortunately, we will probably only be able to fix the issue after #2290 is solved.

[ainar-g]

We will close this issue now, as there will be a lot more work done to make the query log more reliable in #2554.